Bug 18703

Summary: Не работает при загрузке компа - нет автоматич. получения ip-адреса
Product: Branch 5.0 Reporter: Владимир Гусев <vova1971>
Component: dhcpcdAssignee: Mikhail Efremov <sem>
Status: CLOSED FIXED QA Contact: qa-5.0 <qa-5.0>
Severity: normal    
Priority: P2 CC: mike, naf
Version: unspecified   
Hardware: all   
OS: Linux   
Attachments:
Description Flags
Фрагмент syslog от начала загрузки до момента запуска dhcpcd вручную none

Description Владимир Гусев 2009-01-30 20:55:19 MSK
Created attachment 3290 [details]
Фрагмент syslog от начала загрузки до момента запуска dhcpcd вручную

Сегодня обновил dhcpcd для Branch 5.0

[vova@wind ~]$ rpm -qa |grep dhcpcd
dhcpcd-4.0.7-alt2

В итоге, он не стартует ни при загрузке компа, ни при команде service
network start или restart.. Хотя в syslog написано - started

В итоге только после загрузки оконного менеджера вручную по команде от рута: 

dhcpcd wlan0 (или любой другой рабочий интерфейс)..
Comment 1 Nikolay A. Fetisov 2009-02-14 14:11:31 MSK
Складывается впечатление, что в dhcpcd 4.0.x появилась дополнительная проверка на существование в сети хоста с IP, который выделил клиенту сервер DHCP; и эта проверка не работает.


Тестовая система: ALT Server 4.0.1, 3 VE с VETH, объединёнными в мост.
1ая VE - сервер DHCP, 2ая - клиент DHCP на базе M41, dhcpcd-3.0.17-alt4 , 
3ая - клиент DHCP на базе M50, dhcpcd-4.0.10-alt2 . При запуске VE на базе M41 назначает интерфейсу полученный от сервера DHCP адрес, VE на базе M50 - нет.

syslog из M41:
----------
Feb 14 13:32:44 test-3 network: ^IStarting eth0:
Feb 14 13:32:44 test-3 network: .
Feb 14 13:32:44 test-3 last message repeated 2 times
Feb 14 13:32:44 test-3 dhcpcd[14007]: eth0: dhcpcd 3.0.17 starting
Feb 14 13:32:44 test-3 dhcpcd[14007]: eth0: hardware address = 00:18:51:ef:68:72
Feb 14 13:32:44 test-3 dhcpcd[14007]: eth0: broadcasting for a lease
Feb 14 13:32:45 test-3 dhcpcd[14007]: eth0: leased 192.168.2.247 for 21600 seconds
Feb 14 13:32:45 test-3 network: .
Feb 14 13:32:45 test-3 dhcpcd.sh: interface eth0 has been configured with new IP=192.168.2.247
Feb 14 13:32:45 test-3 network: .
Feb 14 13:32:45 test-3 network: OK
----------


syslog из M50:
----------
Feb 14 10:32:16 test-1 network: ^IStarting eth0:
Feb 14 10:32:16 test-1 network: .
Feb 14 10:32:16 test-1 last message repeated 2 times
Feb 14 10:32:16 test-1 network: eth0:
Feb 14 10:32:16 test-1 network: dhcpcd 4.0.10 starting
Feb 14 10:32:16 test-1 dhcpcd[13345]: eth0: dhcpcd 4.0.10 starting
Feb 14 10:32:16 test-1 network: eth0:
Feb 14 10:32:16 test-1 network: hardware address = 00:18:51:fc:c9:07
Feb 14 10:32:16 test-1 network: eth0:
Feb 14 10:32:16 test-1 network: executing `/lib/dhcpcd/dhcpcd-run-hooks', reason PREINIT
Feb 14 10:32:16 test-1 network: eth0:
Feb 14 10:32:16 test-1 network: broadcasting for a lease
Feb 14 10:32:16 test-1 dhcpcd[13345]: eth0: broadcasting for a lease
Feb 14 10:32:16 test-1 network: eth0:
Feb 14 10:32:16 test-1 network: sending DHCP_DISCOVER with xid 0x4f4bd858, next in 4.14 seconds
Feb 14 10:32:16 test-1 network: eth0:
Feb 14 10:32:16 test-1 network: sending DHCP_DISCOVER with xid 0x4f4bd858, next in 8.44 seconds
Feb 14 10:32:17 test-1 network: eth0:
Feb 14 10:32:17 test-1 network: sending DHCP_DISCOVER with xid 0x4f4bd858, next in 15.91 seconds
Feb 14 10:32:17 test-1 network: eth0: sending DHCP_DISCOVER with xid 0x4f4bd858, next in 32.36 seconds
Feb 14 10:32:17 test-1 network: eth0:
Feb 14 10:32:17 test-1 network: offered 192.168.2.248 from 192.168.2.253
Feb 14 10:32:17 test-1 dhcpcd[13345]: eth0: offered 192.168.2.248 from 192.168.2.253
Feb 14 10:32:17 test-1 network: eth0:
Feb 14 10:32:17 test-1 network: sending DHCP_REQUEST with xid 0x4f4bd858, next in 4.59 seconds
Feb 14 10:32:17 test-1 network: eth0:
Feb 14 10:32:17 test-1 network: acknowledged 192.168.2.248 from 192.168.2.253
Feb 14 10:32:17 test-1 dhcpcd[13345]: eth0: acknowledged 192.168.2.248 from 192.168.2.253
Feb 14 10:32:17 test-1 network: eth0:
Feb 14 10:32:17 test-1 network: checking 192.168.2.248 is available on attached networks
Feb 14 10:32:17 test-1 dhcpcd[13345]: eth0: checking 192.168.2.248 is available on attached networks
Feb 14 10:32:17 test-1 network: eth0:
Feb 14 10:32:17 test-1 network: sending ARP probe (1 of 3), next in 1.00 seconds
Feb 14 10:32:17 test-1 network: eth0:
Feb 14 10:32:17 test-1 network: sending ARP probe (2 of 3), next in 1.92 seconds
Feb 14 10:32:17 test-1 network: eth0:
Feb 14 10:32:17 test-1 network: timed out
Feb 14 10:32:17 test-1 dhcpcd[13345]: eth0: timed out
Feb 14 10:32:17 test-1 network: !
Feb 14 10:32:17 test-1 network: .
Feb 14 10:32:17 test-1 network: OK
----------


Вывод tcpdump с HN, при запуске VE на базе M41:
----------
14:03:16.030695 IP 0.0.0.0.bootpc > 255.255.255.255.bootps: BOOTP/DHCP, Request from 00:18:51:ef:68:72, length 300
14:03:16.031455 IP 192.168.2.253.bootps > 192.168.2.247.bootpc: BOOTP/DHCP, Reply, length 300
14:03:16.032454 IP 0.0.0.0.bootpc > 255.255.255.255.bootps: BOOTP/DHCP, Request from 00:18:51:ef:68:72, length 322
14:03:16.033240 IP 192.168.2.253.bootps > 192.168.2.247.bootpc: BOOTP/DHCP, Reply, length 318
----------

То же, при запуске VE на базе M50:
----------
14:00:54.187308 IP 0.0.0.0.bootpc > 255.255.255.255.bootps: BOOTP/DHCP, Request from 00:18:51:fc:c9:07, length 300
14:00:54.188722 IP 192.168.2.253.bootps > 192.168.2.248.bootpc: BOOTP/DHCP, Reply, length 318
14:00:54.189739 IP 0.0.0.0.bootpc > 255.255.255.255.bootps: BOOTP/DHCP, Request from 00:18:51:fc:c9:07, length 309
14:00:54.191419 IP 192.168.2.253.bootps > 192.168.2.248.bootpc: BOOTP/DHCP, Reply, length 318
14:00:54.207266 arp who-has 192.168.2.248 tell 0.0.0.0
14:00:56.094136 arp who-has 192.168.2.248 tell 0.0.0.0
----------

При перезапуске сети (service network restart) в M41:
----------
14:10:28.595428 IP 192.168.2.247.bootpc > 192.168.2.253.bootps: BOOTP/DHCP, Request from 00:18:51:ef:68:72, length 300
14:10:32.921072 IP 0.0.0.0.bootpc > 255.255.255.255.bootps: BOOTP/DHCP, Request from 00:18:51:ef:68:72, length 300
14:10:32.921790 IP 192.168.2.253.bootps > 192.168.2.247.bootpc: BOOTP/DHCP, Reply, length 300
14:10:32.923547 IP 0.0.0.0.bootpc > 255.255.255.255.bootps: BOOTP/DHCP, Request from 00:18:51:ef:68:72, length 322
14:10:32.924788 IP 192.168.2.253.bootps > 192.168.2.247.bootpc: BOOTP/DHCP, Reply, length 318
----------

В M50:
----------
14:07:27.812572 IP 0.0.0.0.bootpc > 255.255.255.255.bootps: BOOTP/DHCP, Request from 00:18:51:fc:c9:07, length 300
14:07:27.813263 IP 192.168.2.253.bootps > 192.168.2.248.bootpc: BOOTP/DHCP, Reply, length 318
14:07:27.815700 IP 0.0.0.0.bootpc > 255.255.255.255.bootps: BOOTP/DHCP, Request from 00:18:51:fc:c9:07, length 309
14:07:27.816305 IP 192.168.2.253.bootps > 192.168.2.248.bootpc: BOOTP/DHCP, Reply, length 318
14:07:27.831660 arp who-has 192.168.2.248 tell 0.0.0.0
14:07:29.546705 arp who-has 192.168.2.248 tell 0.0.0.0
14:07:31.053841 arp who-has 192.168.2.248 tell 0.0.0.0
14:07:35.223936 arp who-has 192.168.2.248 tell 192.168.2.248
14:07:37.226606 arp who-has 192.168.2.248 tell 192.168.2.248
----------
И здесь IP интерфейсу уже назначается.
Comment 2 Michael Shigorin 2009-02-14 14:45:06 MSK
Появилась, причём IMCO неразумно тормозная по части ARP-таймаутов...

Передаю багу sem@, последние сборки dhcpcd в сизифе -- его.
Comment 3 Nikolay A. Fetisov 2009-02-14 14:50:36 MSK
И оно может быть решено для 4.0.10-alt2 или добавлением 'noarp' в /etc/dhcpcd.conf, или удалением из него 'noipv4ll'.
Comment 4 Mikhail Efremov 2009-02-15 02:54:41 MSK
(In reply to comment #3)
> И оно может быть решено для 4.0.10-alt2 или добавлением 'noarp' в
> /etc/dhcpcd.conf,

4.0.10-alt3
Добавил noarp. Действительно эти запросы слишком тормозные, так что вреда от этого похоже больше чем пользы.

>  или удалением из него 'noipv4ll'.
Удаление noipv4ll ничего не даст, там наоборот, noarp подразумевает noipv4ll.
Comment 5 Nikolay A. Fetisov 2009-02-15 06:49:19 MSK
(В ответ на комментарий №4)
> (In reply to comment #3)
>...
> >  или удалением из него 'noipv4ll'.
> Удаление noipv4ll ничего не даст, там наоборот, noarp подразумевает noipv4ll.

Тем не менее, даёт. Т.е., в описанной системе:
- без noipv4ll и без noarp - адрес получается;
- с noipv4ll и без noarp (конфигурация из пакета) - адрес не получается;
- с noipv4ll и с noarp - адрес получается.

И без noipv4ll APR-запросов тоже нет, судя по tcpdump.
Comment 6 Mikhail Efremov 2009-02-16 17:22:17 MSK
(В ответ на комментарий №5)
> И без noipv4ll APR-запросов тоже нет, судя по tcpdump.
Проверил. Судя по tcpdump параметр noipv4ll не влияет на те arp запросы, о которых речь. Если этого параметра нет, dhcpcd использует IPv4LL, если не смог получить адрес от dhcp сервера. В случае
> - без noipv4ll и без noarp - адрес получается;
адрес точно получен от сервера? Впрочем, arp запросы тогда как раз должны присутствовать.
Comment 7 Nikolay A. Fetisov 2009-02-17 09:15:20 MSK
(В ответ на комментарий №6)
> (В ответ на комментарий №5)
> ...
> > - без noipv4ll и без noarp - адрес получается;
> адрес точно получен от сервера? Впрочем, arp запросы тогда как раз должны
> присутствовать.

Они есть, но их больше.


В моей схеме объединены в мост 3 интерфейса VE. Адрес может быть получен только с DHCP-сервера в первом VE. tcpdump запущен на HN:
HN# tcpdump -i vzbr0 -n ether host 00:18:51:fc:c9:07
MAC соответствует интерфейсу VE.

Для M50, dhcpcd-4.0.10-alt3, при запуске VE, с noipv4ll, noarp - конфигурация по-умолчанию:
-----------
09:03:29.263088 IP 0.0.0.0.bootpc > 255.255.255.255.bootps: BOOTP/DHCP, Request from 00:18:51:fc:c9:07, length 300
09:03:29.263777 IP 192.168.2.253.bootps > 192.168.2.248.bootpc: BOOTP/DHCP, Reply, length 314
09:03:29.267443 IP 0.0.0.0.bootpc > 255.255.255.255.bootps: BOOTP/DHCP, Request from 00:18:51:fc:c9:07, length 309
09:03:29.268122 IP 192.168.2.253.bootps > 192.168.2.248.bootpc: BOOTP/DHCP, Reply, length 314
-----------
Адрес получен и назначен интерфейсу.

Только c noipv4ll:
-----------
09:07:17.984722 IP 0.0.0.0.bootpc > 255.255.255.255.bootps: BOOTP/DHCP, Request from 00:18:51:fc:c9:07, length 300
09:07:17.986067 IP 192.168.2.253.bootps > 192.168.2.248.bootpc: BOOTP/DHCP, Reply, length 314
09:07:17.988564 IP 0.0.0.0.bootpc > 255.255.255.255.bootps: BOOTP/DHCP, Request from 00:18:51:fc:c9:07, length 309
09:07:17.990392 IP 192.168.2.253.bootps > 192.168.2.248.bootpc: BOOTP/DHCP, Reply, length 314
09:07:18.005450 arp who-has 192.168.2.248 tell 0.0.0.0
09:07:19.507579 arp who-has 192.168.2.248 tell 0.0.0.0
09:07:21.476320 arp who-has 192.168.2.248 tell 0.0.0.0
-----------
Адрес получен, но интерфейсу _не назначен_.

Без noipv4ll, noarp:
-----------
09:11:29.265566 IP 0.0.0.0.bootpc > 255.255.255.255.bootps: BOOTP/DHCP, Request from 00:18:51:fc:c9:07, length 300
09:11:29.266266 IP 192.168.2.253.bootps > 192.168.2.248.bootpc: BOOTP/DHCP, Reply, length 314
09:11:29.269118 IP 0.0.0.0.bootpc > 255.255.255.255.bootps: BOOTP/DHCP, Request from 00:18:51:fc:c9:07, length 309
09:11:29.269791 IP 192.168.2.253.bootps > 192.168.2.248.bootpc: BOOTP/DHCP, Reply, length 314
09:11:29.286231 arp who-has 192.168.2.248 tell 0.0.0.0
09:11:30.436363 arp who-has 192.168.2.248 tell 0.0.0.0
09:11:32.396273 arp who-has 192.168.2.248 tell 0.0.0.0
09:11:38.684123 arp who-has 192.168.2.248 tell 192.168.2.248
09:11:41.507615 arp who-has 192.168.2.248 tell 192.168.2.248
-----------
Адрес получен и назначен интерфейсу.
Comment 8 Mikhail Efremov 2009-02-17 19:40:49 MSK
(В ответ на комментарий №7)
> 09:07:18.005450 arp who-has 192.168.2.248 tell 0.0.0.0
> 09:07:19.507579 arp who-has 192.168.2.248 tell 0.0.0.0
> 09:07:21.476320 arp who-has 192.168.2.248 tell 0.0.0.0
> -----------
> Адрес получен, но интерфейсу _не назначен_.

dhcpcd при этом отвалился по таймауту?
Какое значение DHCP_TIMEOUT в /etc/net/options.d?
Такое впечатление, что маленький.
Если так, то все понятно. При включенном IPv4LL dhcpcd устанавливет exit timeout как timeout + 10 сек., при выключенном (noipv4ll) - ровно timeout сек.
Если таймаут маленький, dhcpcd с опцией noipv4ll просто не успевает установить адрес, истекает таймаут.
Comment 9 Nikolay A. Fetisov 2009-02-18 13:24:02 MSK
(В ответ на комментарий №8)
> dhcpcd при этом отвалился по таймауту?
Отваливается, соответствующая строка в /var/log/messages из комментария #1 присустствует.

> Какое значение DHCP_TIMEOUT в /etc/net/options.d?
> Такое впечатление, что маленький.
Значение из коробки, etcnet-defaults-server-0.9.7-alt2, DHCP_TIMEOUT=30

> Если так, то все понятно.
Да, похоже на это. При DHCP_TIMEOUT=40 адрес назначается и без noarp.
Comment 10 Mikhail Efremov 2009-02-18 20:38:36 MSK
(В ответ на комментарий №9)
> > Какое значение DHCP_TIMEOUT в /etc/net/options.d?
> > Такое впечатление, что маленький.
> Значение из коробки, etcnet-defaults-server-0.9.7-alt2, DHCP_TIMEOUT=30

Тогда все равно не понятно. Судя по логу ведь явно не 30 секунд проходит с момента старта dhcpcd, а максимум 2. И я не вижу ничего, что могло сломаться в передаче DHCP_TIMEOUT при старте dhcpcd.
Comment 11 Nikolay A. Fetisov 2009-02-18 22:03:19 MSK
(В ответ на комментарий №10)
>... Судя по логу ведь явно не 30 секунд проходит с
> момента старта dhcpcd, а максимум 2. ...

Ну, это-то объяснить легко. syslogd пишет не время получения сообщения от приложения, а время записи этого сообщения на диск (почему так - это уже другой вопрос). На данной машинке "диск" - это карта CF, и при запуске VE значение await, выдаваемое iostat, составляет порядка 9-10 секунд.
Т.е., в лог сообщения пишутся с очень приличной задержкой - и подряд.

Смотреть имеет смысл только временные отметки tcpdump, там видно, что посылки запросов ARP занимают порядка 3 секунд без noarp, и 10 секунд - без noipv4ll.
Comment 12 Mikhail Efremov 2009-02-19 22:23:47 MSK
(В ответ на комментарий №11)
> (В ответ на комментарий №10)
> Ну, это-то объяснить легко. ...

Теперь ясно, спасибо. Таким образом вопрос, думаю, окончательно исчерпан, наконец :)
Comment 13 Nikolay A. Fetisov 2009-02-20 10:44:56 MSK
(В ответ на комментарий №12)
> Теперь ясно, спасибо. 

Спасибо за оперативное решение проблемы.

> Таким образом вопрос, думаю, окончательно исчерпан,
> наконец :)

А это вопрос к открывшему ошибку :)