Bug 40687

Summary: udev: тупит при загрузке (init == propagator)
Product: Sisyphus Reporter: Alexey Sheplyakov <asheplyakov>
Component: propagatorAssignee: Anton Farygin <rider>
Status: CLOSED FIXED QA Contact: qa-sisyphus
Severity: normal    
Priority: P5 CC: antohami, darktemplar, iv, jqt4, mike, rider, sem, sin, voropaevdmtr, zerg
Version: unstable   
Hardware: aarch64   
OS: Linux   
Bug Depends on:    
Bug Blocks: 40766    
Attachments:
Description Flags
setup-mate-nocomposite.spec none

Description Alexey Sheplyakov 2021-08-09 17:10:50 MSK
Загружаю компьютер по сети, примерно так:

# cat /proc/cmdline 
vmlinuz initrd=full.cz changedisk fastboot live automatic=method:http,network:dhcp,server:10.42.0.2,directory:/netboot/alt-p9-gnome3-20210531-aarch64.iso stagename=live showopts console=ttyS0,115200n8 earlycon=uart8250,mmio32,0x20230000

Наблюдаю зависание минуты на 3 после того, как propagator закончил "Loading program to memory". После этого в консоли появляется сообщение:

Worker [XYZ] processing SEQNUM=ABCD is taking a long time

(где XYZ и ABCD - не слишком большие натуральные числа), после чего загрузка продолжается нормально.

Более подробный лог [1]:

loop3: Device (SEQNUM=2445, ACTION=change) ready for processing
Successfully forked off 'n/a' as PID 197.
loop3: Worker [197] is forked for processing SEQNUM=2445.
loop3: Device (SEQNUM=2446, ACTION=change) is queued
loop3: SEQNUM=2446 blocked by SEQNUM=2445
loop3: Processing device (SEQNUM=2445, ACTION=change)
loop3: /etc/udev/rules.d/60-persistent-storage.rules:113 Importing properties from results of builtin command 'blkid'
loop3: Probe /dev/loop3 with raid and offset=0
loop3: Worker [197] processing SEQNUM=2445 is taking a long time
loop3: Worker [197] processing SEQNUM=2445 killed
Worker [197] terminated by signal 9 (KILL)
loop3: Worker [197] failed
loop3: sd-device-monitor: Passed 204 byte to netlink monitor
Validate module index
Check if link configuration needs reloading.
loop3: Device (SEQNUM=2446, ACTION=change) ready for processing
Successfully forked off 'n/a' as PID 201.
loop3: Worker [201] is forked for processing SEQNUM=2446.
loop3: Processing device (SEQNUM=2446, ACTION=change)
loop3: /etc/udev/rules.d/60-persistent-storage.rules:113 Importing properties from results of builtin command 'blkid'
loop3: Probe /dev/loop3 with raid and offset=0
loop0: Device (SEQNUM=2447, ACTION=change) is queued
loop0: Device (SEQNUM=2447, ACTION=change) ready for processing
loop0: Device (SEQNUM=2448, ACTION=change) is queued
loop0: Device (SEQNUM=2447, ACTION=change) ready for processing
loop0: SEQNUM=2448 blocked by SEQNUM=2447
Reading EFI variable /sys/firmware/efi/efivars/LoaderDevicePartUUID-4a67b082-0a4c-41cf-b6c7-440b29bb8c4f.
open("/sys/firmware/efi/efivars/LoaderDevicePartUUID-4a67b082-0a4c-41cf-b6c7-440b29bb8c4f") failed: No such file or directory
loop3: /etc/udev/rules.d/60-persistent-storage.rules:116 LINK 'disk/by-uuid/2021-05-31-13-01-20-00'
loop3: /etc/udev/rules.d/60-persistent-storage.rules:117 LINK 'disk/by-label/ALT\x20p9\x20gnome3\x2faarch64'
loop3: Handling device node '/dev/loop3', devnum=b7:3
loop3: Preserve already existing symlink '/dev/block/7:3' to '../loop3'
loop3: Creating symlink '/dev/disk/by-uuid/2021-05-31-13-01-20-00' to '../../loop3'
loop3: Creating symlink '/dev/disk/by-label/ALT\x20p9\x20gnome3\x2faarch64' to '../../loop3'
loop3: sd-device: Created db file '/run/udev/data/b7:3' for '/devices/virtual/block/loop3'
loop3: Device (SEQNUM=2446, ACTION=change) processed
loop3: sd-device-monitor: Passed 717 byte to netlink monitor
loop0: Device (SEQNUM=2447, ACTION=change) ready for processing
loop0: sd-device-monitor: Passed 205 byte to netlink monitor
loop0: Processing device (SEQNUM=2447, ACTION=change)
loop0: /etc/udev/rules.d/60-persistent-storage.rules:113 Importing properties from results of builtin command 'blkid'
loop0: Probe /dev/loop0 with raid and offset=0
loop0: Handling device node '/dev/loop0', devnum=b7:0
loop0: Preserve already existing symlink '/dev/block/7:0' to '../loop0'
loop0: sd-device: Created db file '/run/udev/data/b7:0' for '/devices/virtual/block/loop0'
loop0: Device (SEQNUM=2447, ACTION=change) processed
loop0: sd-device-monitor: Passed 266 byte to netlink monitor
loop0: Device (SEQNUM=2448, ACTION=change) ready for processing
loop0: sd-device-monitor: Passed 195 byte to netlink monitor
loop0: Processing device (SEQNUM=2448, ACTION=change)
loop0: /etc/udev/rules.d/60-persistent-storage.rules:113 Importing properties from results of builtin command 'blkid'
loop0: Probe /dev/loop0 with raid and offset=0
loop0: Handling device node '/dev/loop0', devnum=b7:0
loop0: Preserve already existing symlink '/dev/block/7:0' to '../loop0'
loop0: sd-device: Created db file '/run/udev/data/b7:0' for '/devices/virtual/block/loop0'
loop0: Device (SEQNUM=2448, ACTION=change) processed



[1] получен подкладыванием в full.cz такого /etc/udev/udev.conf

udev_log=debug
max_children=1
Comment 1 Alexey Sheplyakov 2021-08-11 20:43:34 MSK
Похоже это propagator виноват
Comment 2 Alexey Sheplyakov 2021-08-11 20:44:53 MSK
Хорошо воспроизводится и в p10/сизифе. Виснет *наверное* здесь:

#0  0x0000ffff823e8740 in __libc_read (fd=12, buf=0xffff81dea038, nbytes=nbytes@entry=262144) at ../sysdeps/unix/sysv/linux/read.c:26
#1  0x0000ffff82451b64 in read (__nbytes=262144, __buf=<optimized out>, __fd=<optimized out>) at /usr/include/bits/unistd.h:46
#2  read_buffer (len=262144, real_off=1831862272, pr=0xaaab03436e10) at libblkid/src/probe.c:564
#3  blkid_probe_get_buffer (pr=pr@entry=0xaaab03436e10, off=off@entry=1831862272, len=len@entry=262144) at libblkid/src/probe.c:678
#4  0x0000ffff82465b60 in probe_zfs (pr=0xaaab03436e10, mag=<optimized out>) at libblkid/src/superblocks/zfs.c:287
#5  0x0000ffff824623cc in superblocks_probe (pr=pr@entry=0xaaab03436e10, chn=chn@entry=0xaaab03436e70) at libblkid/src/superblocks/superblocks.c:412
#6  0x0000ffff824629e4 in superblocks_safeprobe (pr=0xaaab03436e10, chn=0xaaab03436e70) at libblkid/src/superblocks/superblocks.c:474
#7  0x0000ffff82454020 in blkid_do_safeprobe (pr=pr@entry=0xaaab03436e10) at libblkid/src/probe.c:1389
#8  0x0000aaaae6f04c7c in probe_superblocks (pr=0xaaab03436e10) at ../src/udev/udev-builtin-blkid.c:234
#9  builtin_blkid (dev=0xaaab03461df0, argc=<optimized out>, argv=<optimized out>, test=false) at ../src/udev/udev-builtin-blkid.c:320
#10 0x0000aaaae6ef3bb0 in udev_builtin_run (dev=dev@entry=0xaaab03461df0, cmd=cmd@entry=UDEV_BUILTIN_BLKID, command=command@entry=0xffffd2d31ba8 "blkid", test=test@entry=false)
    at ../src/udev/udev-builtin.c:127
#11 0x0000aaaae6ef5ae8 in udev_rule_apply_token_to_event (rules=rules@entry=0xaaab0342ac50, dev=0xaaab03461df0, event=event@entry=0xaaab03449ad0, timeout_usec=timeout_usec@entry=600000000, 
    timeout_signal=timeout_signal@entry=9, properties_list=properties_list@entry=0xaaab034205a8) at ../src/udev/udev-rules.c:1832
#12 0x0000aaaae6ef8930 in udev_rule_apply_line_to_event (next_line=<synthetic pointer>, properties_list=0xaaab034205a8, timeout_signal=9, timeout_usec=600000000, event=0xaaab03449ad0, 
    rules=0xaaab0342ac50) at ../src/udev/udev-rules.c:2328
#13 udev_rules_apply_to_event (rules=0xaaab0342ac50, event=0xaaab03449ad0, timeout_usec=600000000, timeout_signal=9, properties_list=0xaaab034205a8) at ../src/udev/udev-rules.c:2356
#14 0x0000aaaae6eec73c in udev_event_execute_rules (event=0xaaab03449ad0, inotify_fd=<optimized out>, timeout_usec=600000000, timeout_signal=9, properties_list=0xaaab034205a8, 
    rules=0xaaab0342ac50) at ../src/udev/udev-event.c:1032
#15 0x0000aaaae6ee64a0 in worker_process_device (dev=0xaaab03461df0, manager=0xaaab0341fc50) at ../src/udev/udevd.c:489
#16 worker_device_monitor_handler (monitor=monitor@entry=0xaaab03441d10, dev=dev@entry=0xaaab03461df0, userdata=userdata@entry=0xaaab0341fc50) at ../src/udev/udevd.c:520
#17 0x0000aaaae6ee7e50 in worker_main (first_device=0xaaab03461df0, monitor=<optimized out>, _manager=0xaaab0341fc50) at ../src/udev/udevd.c:585
#18 worker_spawn (event=0xaaab03439fe0, manager=0xaaab0341fc50) at ../src/udev/udevd.c:623
#19 event_run (event=0xaaab03439fe0, manager=0xaaab0341fc50) at ../src/udev/udevd.c:683
#20 event_queue_start (manager=manager@entry=0xaaab0341fc50) at ../src/udev/udevd.c:962
#21 0x0000aaaae6ee85c4 in on_uevent (monitor=<optimized out>, dev=0xaaab03461df0, userdata=0xaaab0341fc50) at ../src/udev/udevd.c:1061
#22 0x0000aaaae6f1f89c in device_monitor_event_handler (s=<optimized out>, fd=<optimized out>, revents=<optimized out>, userdata=0xaaab0341fdb0)
    at ../src/libsystemd/sd-device/device-monitor.c:238
#23 0x0000aaaae6f37690 in source_dispatch (s=0xaaab03421bc0) at ../src/libsystemd/sd-event/sd-event.c:3504
#24 0x0000aaaae6f3821c in sd_event_dispatch (e=0xaaab0341ff20) at ../src/libsystemd/sd-event/sd-event.c:4078
#25 sd_event_run (timeout=18446744073709551615, e=<optimized out>) at ../src/libsystemd/sd-event/sd-event.c:4139
#26 sd_event_loop (e=0xaaab0341ff20) at ../src/libsystemd/sd-event/sd-event.c:4160
#27 0x0000aaaae6ed883c in main_loop (manager=0xaaab0341fc50) at ../src/udev/udevd.c:1823
#28 run_udevd (argv=<optimized out>, argc=<optimized out>) at ../src/udev/udevd.c:1935
#29 run (argv=<optimized out>, argc=<optimized out>) at ../src/udev/udevadm.c:116
#30 main (argc=<optimized out>, argv=<optimized out>) at ../src/udev/udevadm.c:133

"Наверное" -- потому, что в initrd gdb/gdbserver далеко не всегда работает.
Пока что удалось прицепиться к зависшему udevd только один раз, и backtrace вот такой.
Comment 3 Alexey Sheplyakov 2021-08-11 20:45:21 MSK
#282445 TESTED #1 [test-only] sisyphus propagator.git=20210811-alt1
Comment 4 Evgeny Sinelnikov 2021-08-12 12:19:40 MSK
Предлагаю пересобрать и потестировать на этой сборке propagator некоторые starterkits для x86_64 и aarch64 - mate, gnome, rescue.
Comment 5 Антон Мидюков 2021-08-12 12:22:42 MSK
(In reply to Evgeny Sinelnikov from comment #4)
> Предлагаю пересобрать и потестировать на этой сборке propagator некоторые
> starterkits для x86_64 и aarch64 - mate, gnome, rescue.

Хорошо. Соберу.
Comment 6 Антон Мидюков 2021-08-12 12:33:44 MSK
(In reply to Alexey Sheplyakov from comment #3)
> #282445 TESTED #1 [test-only] sisyphus propagator.git=20210811-alt1

Не доступно. Я так понимаю, актуальное:
[#282489] TESTED propagator.git=20210811-alt1

?
Comment 7 Антон Мидюков 2021-08-12 17:35:08 MSK
(In reply to Антон Мидюков from comment #6)
> (In reply to Alexey Sheplyakov from comment #3)
> > #282445 TESTED #1 [test-only] sisyphus propagator.git=20210811-alt1
> 
> Не доступно. Я так понимаю, актуальное:
> [#282489] TESTED propagator.git=20210811-alt1
> 
> ?

Собрал с этим заданием в:
http://nightly.altlinux.org/p10/beta/
http://nightly.altlinux.org/p10-aarch64/beta/
Comment 8 Alexey Sheplyakov 2021-08-13 15:41:39 MSK
(In reply to Антон Мидюков from comment #7)
> (In reply to Антон Мидюков from comment #6)
> > (In reply to Alexey Sheplyakov from comment #3)
> > > #282445 TESTED #1 [test-only] sisyphus propagator.git=20210811-alt1
> > 
> > Не доступно. Я так понимаю, актуальное:
> > [#282489] TESTED propagator.git=20210811-alt1
> > 

Тоже подойдёт (кроме исправления $subj там ещё 1) улучшение загрузки по http, и 2) загрузка без ramdisk_size).


> Собрал с этим заданием в:
> http://nightly.altlinux.org/p10/beta/
> http://nightly.altlinux.org/p10-aarch64/beta/

Спасибо. Проверили локальную загрузку с alt-p10-mate-20210812-x86_64.iso. Упорно делает вид, что работает. Правда, automatic=cdrom всё равно монтирует stage2 с носителя (даже если НЕ указан параметр lowmem). Но это уже тема другого для другого бага.
Comment 9 Alexey Sheplyakov 2021-08-13 19:25:33 MSK
Проверили загрузку с alt-p10-mate-20210812-aarch64.iso на плате TF307 (с процессором BE-M1000).

Загружали локально с ISO и по сети через HTTP. Загружается. Но пользоваться этим невозможно. Открываем терминал, нажимаем Ctrl-L - и всё, сеанс окончен.

Running Xsession[2363] /usr/bin/mate-session
Agent pid 2404
gnome-keyring-daemon: no process capabilities, insecure memory might get used
** Message: 16:18:34.069: couldn't access control socket: /run/user/500/keyring/control: No such file or directory
mate-session[2363]: WARNING: Unable to find provider '' of required component 'dock'
SSH_AUTH_SOCK=/run/user/500/keyring/ssh
Window manager warning: Log level 128: unsetenv() is not thread-safe and should not be used after threads are created
gnome-keyring-daemon: no process capabilities, insecure memory might get used
SSH_AUTH_SOCK=/run/user/500/keyring/ssh
Looking in '/etc/xdg/parcellite/parcelliterc'
Looking in '/etc/xdg/parcellite/parcelliterc'
gnome-keyring-daemon: no process capabilities, insecure memory might get used
SSH_AUTH_SOCK=/run/user/500/keyring/ssh

(caja:2493): Gtk-WARNING **: 16:18:35.289: Failed to register client: GDBus.Error:org.gnome.SessionManager.AlreadyRegistered: Unable to register client
Flag 0x0001, status 0, EXIT 1 STAT 0
Initializing caja-image-converter extension
Initializing caja-open-terminal extension

Xorg завершается штатно.
Comment 10 Антон Мидюков 2021-08-13 20:08:04 MSK
(In reply to Alexey Sheplyakov from comment #9)
> Проверили загрузку с alt-p10-mate-20210812-aarch64.iso на плате TF307 (с
> процессором BE-M1000).
> 
> Загружали локально с ISO и по сети через HTTP. Загружается. Но пользоваться
> этим невозможно. Открываем терминал, нажимаем Ctrl-L - и всё, сеанс окончен.
> 
> Running Xsession[2363] /usr/bin/mate-session
> Agent pid 2404
> gnome-keyring-daemon: no process capabilities, insecure memory might get used
> ** Message: 16:18:34.069: couldn't access control socket:
> /run/user/500/keyring/control: No such file or directory
> mate-session[2363]: WARNING: Unable to find provider '' of required
> component 'dock'
> SSH_AUTH_SOCK=/run/user/500/keyring/ssh
> Window manager warning: Log level 128: unsetenv() is not thread-safe and
> should not be used after threads are created
> gnome-keyring-daemon: no process capabilities, insecure memory might get used
> SSH_AUTH_SOCK=/run/user/500/keyring/ssh
> Looking in '/etc/xdg/parcellite/parcelliterc'
> Looking in '/etc/xdg/parcellite/parcelliterc'
> gnome-keyring-daemon: no process capabilities, insecure memory might get used
> SSH_AUTH_SOCK=/run/user/500/keyring/ssh
> 
> (caja:2493): Gtk-WARNING **: 16:18:35.289: Failed to register client:
> GDBus.Error:org.gnome.SessionManager.AlreadyRegistered: Unable to register
> client
> Flag 0x0001, status 0, EXIT 1 STAT 0
> Initializing caja-image-converter extension
> Initializing caja-open-terminal extension
> 
> Xorg завершается штатно.

На Raspberry Pi 4 на этом же образе эта проблема не воспроизводится.
По ctr+L очищается экран терминала. Сложный графический эффект для Байкала?
Comment 11 Evgeny Sinelnikov 2021-08-13 22:14:08 MSK
Ну, такая проблема бывает с этим gnome-keyring-daemon:
- https://forums.opensuse.org/showthread.php/529753-How-to-fix-quot-access-control-socket-keyring-control-quot-error
- https://forums.opensuse.org/showthread.php/529517-XDM-and-gnome-keyring

Это может быть: "GNOME compatibility is enabled" / "gnome-keyring-daemon: insufficient process capabilities, insecure memory might get used": they might point to a misconfiguration":
- https://forums.opensuse.org/showthread.php/541216-Slow-starting-at-boot/page2

Что не так на байклале с этим самым capability:
- https://unix.stackexchange.com/questions/112030/gnome-keyring-daemon-insufficient-process-capabilities-unsecure-memory-might-g

What happens is that the gkd process does not have the ability to perform a CAP_IPC_LOCK to lock memory. If your filesystem supports capabilities, you can give the executable this capability with this terminal command:
 sudo setcap cap_ipc_lock=+ep `which gnome-keyring-daemon`
Comment 12 Alexey Sheplyakov 2021-08-15 16:43:21 MSK
(In reply to Антон Мидюков from comment #10)

> На Raspberry Pi 4 на этом же образе эта проблема не воспроизводится.

На raspberry pi 4 этот образ загружается с efifb. Так что сравнение такое себе.

> По ctr+L очищается экран терминала. Сложный графический эффект для Байкала?

Сложный графический эффект для mate.  

# systemctl stop lightdm
# rmmod panfrost
# systemctl start lightdm

И вот теперь, если запустить терминал и нажать Ctrl-L - сеанс завершается.
Mate зачем-то позарез нужен аппаратный GL (ES). На llvmpipe mate категорически не согласен.
Но как-то он ухитряется работать с efifb/fbdevhw.

А аппаратный GL ES с этим образом не доступен из-за странного/старого ядра.
Странность в том, что

1) присутствует полу-закрытый драйвер GPU mali_kbase
2) Для загрузки драйвера panfrost требуется дополнительный параметр.

В результате первым загружается модуль mali_kbase, для которого в userspace нет ответной части,
и аппаратный GL ES недоступен. Просто так выгрузить mali_kbase и вместо него загрузить
panfrost не выходит - mali_kbase оставляет GPU в полу-зависшем состоянии, так что помогает
только перезагрузка (c параметром modprobe.blacklist=mali_kbase).
Comment 13 Michael Shigorin 2021-08-16 10:38:06 MSK
Created attachment 9586 [details]
setup-mate-nocomposite.spec

Возможно, пригодится:

[org.mate.Marco.general]
compositing-manager = false
Comment 14 Антон Мидюков 2021-08-16 12:08:51 MSK
(In reply to Michael Shigorin from comment #13)
> Created attachment 9586 [details]
> setup-mate-nocomposite.spec
> 
> Возможно, пригодится:
> 
> [org.mate.Marco.general]
> compositing-manager = false

или пакет mate-reduced-resource тогда уж.
Comment 15 Alexey Sheplyakov 2021-08-16 18:39:29 MSK
(In reply to Michael Shigorin from comment #13)
> Created attachment 9586 [details]
> setup-mate-nocomposite.spec
> 
> Возможно, пригодится:
> 
> [org.mate.Marco.general]
> compositing-manager = false

Спасибо, но это не совсем то, что нужно. Подпирать костылями для каждой платы (да ещё и в зависимости от набора загруженных модулей) - плохо масштабируется.
Comment 16 Alexey Sheplyakov 2021-08-16 18:41:51 MSK
(In reply to Антон Мидюков from comment #7)
> (In reply to Антон Мидюков from comment #6)
> > (In reply to Alexey Sheplyakov from comment #3)
> > > #282445 TESTED #1 [test-only] sisyphus propagator.git=20210811-alt1
> > 
> > Не доступно. Я так понимаю, актуальное:
> > [#282489] TESTED propagator.git=20210811-alt1
> > 
> > ?
> 
> Собрал с этим заданием в:
> http://nightly.altlinux.org/p10/beta/

Проверил загрузку по сети на x86_64 машине (NUC7i3BNB).
mate и gnome 3 загружаются (и по http, и по cifs), и упорно делают вид, что работают.

> http://nightly.altlinux.org/p10-aarch64/beta/
Comment 17 Evgeny Sinelnikov 2021-08-16 22:02:22 MSK
Предлагаю сделать уже не тестовую сборку и, после падения в EPERM, дожидаться одобрения.
Comment 18 Alexey Sheplyakov 2021-08-17 17:03:51 MSK
(In reply to Evgeny Sinelnikov from comment #17)
> Предлагаю сделать уже не тестовую сборку и, после падения в EPERM,
> дожидаться одобрения.


#282489 EPERM #2 sisyphus propagator.git=20210811-alt1
Comment 19 Anton Farygin 2021-08-17 17:11:21 MSK
@zerg тут неплохо было бы сделать review изменений. спасибо.
Comment 20 Sergey V Turchin 2021-08-17 17:22:34 MSK
> бы сделать review изменений
2 darktemplar: посмотри, пожалуйста, http://git.altlinux.org/tasks/282489/gears/100/git
Comment 21 Sergey V Turchin 2021-08-18 11:39:04 MSK
(Ответ для Anton Farygin на комментарий #19)
> @zerg тут неплохо было бы сделать review изменений. спасибо.
Создал задачу во внутренней кухне.
Comment 22 Repository Robot 2021-08-31 15:20:35 MSK
propagator-20210823-alt1 -> sisyphus:

 Mon Aug 23 2021 Alexey Sheplyakov <asheplyakov@altlinux> 20210823-alt1
 - Avoid deadlock between udev probing stage2 and stage1 mounting it (closes: #40687)