Bug 14409

Summary:	modprobe race during early boot
Product:	Sisyphus	Reporter:	Ivan Zakharyaschev <imz>
Component:	module-init-tools	Assignee:	Alexey Gladkov <legion>
Status:	CLOSED FIXED	QA Contact:	qa-sisyphus
Severity:	normal
Priority:	P2	CC:	hsvhome, ldv, mike, shrek, silicium, vsu
Version:	unstable
Hardware:	all
OS:	Linux

Description Ivan Zakharyaschev 2008-02-13 10:35:40 MSK

In kernel-image-std-def-2.6.24-alt2 and in kernel-image-std-def-2.6.24-alt3.

I do not feel that something is not working in the system because of this, but I
discovered these warnings.
Steps to Reproduce:
1. boot
2.
3.
Actual Results:  
The warnings:

# fgrep -i 'unknown symbol' -r /var/log | fgrep 09:53
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_pci_suspend
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_resume_root_hub
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_pci_probe
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_unlink_urb_from_ep
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_disabled
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_check_unlink_urb
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_calc_bus_time
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_link_urb_to_ep
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_pci_resume
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_giveback_urb
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_poll_rh_status
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_pci_remove
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_root_hub_lost_power
# 

Everything uhci_hcd-related:

# fgrep -i uhci_hcd -r /var/log | fgrep 09:53
/var/log/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.0: UHCI Host
Controller
/var/log/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.0: new USB
bus registered, assigned bus number 1
/var/log/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.0: irq 16, io
base 0x0000bf80
/var/log/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.1: UHCI Host
Controller
/var/log/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.1: new USB
bus registered, assigned bus number 2
/var/log/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.1: irq 18, io
base 0x0000bf60
/var/log/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.2: UHCI Host
Controller
/var/log/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.2: new USB
bus registered, assigned bus number 3
/var/log/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.2: irq 19, io
base 0x0000bf40
/var/log/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.3: UHCI Host
Controller
/var/log/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.3: new USB
bus registered, assigned bus number 4
/var/log/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.3: irq 17, io
base 0x0000bf20
/var/log/messages:Feb 13 09:53:46 dell kernel: usb 4-2: new low speed USB device
using uhci_hcd and address 2
/var/log/kernel/info:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.0: UHCI
Host Controller
/var/log/kernel/info:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.0: new USB
bus registered, assigned bus number 1
/var/log/kernel/info:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.0: irq 16,
io base 0x0000bf80
/var/log/kernel/info:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.1: UHCI
Host Controller
/var/log/kernel/info:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.1: new USB
bus registered, assigned bus number 2
/var/log/kernel/info:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.1: irq 18,
io base 0x0000bf60
/var/log/kernel/info:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.2: UHCI
Host Controller
/var/log/kernel/info:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.2: new USB
bus registered, assigned bus number 3
/var/log/kernel/info:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.2: irq 19,
io base 0x0000bf40
/var/log/kernel/info:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.3: UHCI
Host Controller
/var/log/kernel/info:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.3: new USB
bus registered, assigned bus number 4
/var/log/kernel/info:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.3: irq 17,
io base 0x0000bf20
/var/log/kernel/info:Feb 13 09:53:46 dell kernel: usb 4-2: new low speed USB
device using uhci_hcd and address 2
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_pci_suspend
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_resume_root_hub
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_pci_probe
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_unlink_urb_from_ep
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_disabled
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_check_unlink_urb
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_calc_bus_time
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_link_urb_to_ep
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_pci_resume
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_giveback_urb
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_poll_rh_status
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_hcd_pci_remove
/var/log/kernel/warnings:Feb 13 09:53:46 dell kernel: uhci_hcd: Unknown symbol
usb_root_hub_lost_power
/var/log/syslog/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.0:
UHCI Host Controller
/var/log/syslog/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.0: new
USB bus registered, assigned bus number 1
/var/log/syslog/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.0: irq
16, io base 0x0000bf80
/var/log/syslog/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.1:
UHCI Host Controller
/var/log/syslog/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.1: new
USB bus registered, assigned bus number 2
/var/log/syslog/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.1: irq
18, io base 0x0000bf60
/var/log/syslog/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.2:
UHCI Host Controller
/var/log/syslog/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.2: new
USB bus registered, assigned bus number 3
/var/log/syslog/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.2: irq
19, io base 0x0000bf40
/var/log/syslog/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.3:
UHCI Host Controller
/var/log/syslog/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.3: new
USB bus registered, assigned bus number 4
/var/log/syslog/messages:Feb 13 09:53:46 dell kernel: uhci_hcd 0000:00:1d.3: irq
17, io base 0x0000bf20
/var/log/syslog/messages:Feb 13 09:53:46 dell kernel: usb 4-2: new low speed USB
device using uhci_hcd and address 2
#

Comment 1 Sergey Vlasov 2008-02-13 13:19:33 MSK

This sometimes happen during boot, because locking in modprobe does not work
until the root filesystem is remounted read-write, and udevd (which also
triggers lots of concurrent modprobe calls) now starts when the root fs is still
readonly.

One possible solution is to replace fcntl() locking in modprobe with flock() -
these locks are purely local anyway, and flock(fd, LOCK_EX) is possible even
when fd was opened with O_RDONLY. BTW, old modutils used flock() there.

Comment 2 Ivan Zakharyaschev 2008-05-07 23:07:25 MSD

A comment by vsu someone might find useful --
https://bugzilla.altlinux.org/show_bug.cgi?id=14411#c1 :

the uhci_hcd problem is due to races between concurrent
modprobe invocations.

Comment 3 Michail Yakushin 2008-05-29 10:54:10 MSD

*** Bug 15550 has been marked as a duplicate of this bug. ***

Comment 4 Sergey Shilov 2008-06-14 22:41:16 MSD

(In reply to comment #3)
> *** Bug 15550 has been marked as a duplicate of this bug. ***
> 
At last std-def kernel i no see correspond error messages.
The bug is FIXED?

Comment 5 Valery Inozemtsev 2009-05-17 14:23:19 MSD

fixed

Comment 6 Dmitry V. Levin 2009-05-17 14:44:33 MSD

(In reply to comment #5)
> fixed

где fixed, каким коммитом?

Comment 7 Valery Inozemtsev 2009-05-17 14:48:15 MSD

это было давно и насколько я помню не в module-init-tools

Comment 8 Dmitry V. Levin 2009-05-17 14:59:38 MSD

(In reply to comment #7)
> это было давно и насколько я помню не в module-init-tools

Если проблема не исправлена в module-init-tools, то она ещё не исправлена, и всплывёт в аналогичной ситуации.

Comment 9 Sergey Vlasov 2009-09-03 18:55:39 MSD

(В ответ на комментарий №6)
> где fixed, каким коммитом?

Исправлено в ядре, начиная с 2.6.25:

commit c9a3ba55bb5da03fc7d707709a7fe078fe1aa0a0
Author: Rusty Russell
Date:   Tue Jan 29 17:13:18 2008 -0500

    module: wait for dependent modules doing init.
    
    There have been reports of modules failing to load because the modules
    they depend on are still loading.  This changes the modules to wait
    for a reasonable length of time in that case.  We time out eventually,
    because there can be module loops or broken modules.

Изначально проблема возникла из-за того, что при выполнении системного вызова init_module() вызывается функция инициализации модуля, которая в общем случае может выполняться сколь угодно долго, и в это время не блокируются другие вызовы init_module(), однако модуль ещё не инициализирован полностью, и экспортируемые им символы не могут использоваться другими модулями. Блокировка в modprobe устраняла именно эту проблему - зависимые модули не загружались, пока не снималась блокировка с базового модуля (после завершения его инициализации).

При использовании ядра >= 2.6.25, если при загрузке модуля обнаруживается, что какие-либо из необходимых для него символов предоставляются модулями, которые ещё не были полностью инициализированы, вместо немедленной выдачи ошибки ожидается завершение инициализации требуемых модулей (максимум 30 секунд). Блокировка на уровне modprobe в этом случае не требуется (и в последних версиях module-init-tools код, выполнявший эту блокировку, был удалён).