Ubuntu 10.04.2: perda de conexão eth0 : bug no dhclient?

[leandrojk]

  Olá,

   Uso Ubuntu 10.04.2 e minha máquina está perdendo conexão com a rede (via eth0). Observando o arquivo syslog (ver abaixo), parece que o dhclient não consegue renovar o endereço IP (obtido via DHCP). Parece que o dhclient e o NetworkManager não estão se entendendo.  Conversei com o administrador da rede e, aparentemente, não há nada de errado com o servidor DHCP.  Alguém saberia dizer se as msgs abaixo indicam problema na placa de rede ou algum bug de software?

    Agradeço qualquer ajuda.

  Leandro



Feb 23 10:03:56 leandro-desktop dhclient: DHCPREQUEST of 150.162.60.129 on eth0 to 150.162.60.5 port 67
Feb 23 10:03:56 leandro-desktop dhclient: DHCPACK of 150.162.60.129 from 150.162.60.5
Feb 23 10:03:56 leandro-desktop dhclient: bound to 150.162.60.129 -- renewal in 8126 seconds.
Feb 23 10:17:01 leandro-desktop CRON[5526]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 23 11:17:01 leandro-desktop CRON[5532]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 23 12:17:01 leandro-desktop CRON[5538]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 23 12:19:22 leandro-desktop dhclient: DHCPREQUEST of 150.162.60.129 on eth0 to 150.162.60.5 port 67
Feb 23 12:19:22 leandro-desktop dhclient: DHCPACK of 150.162.60.129 from 150.162.60.5
Feb 23 12:19:22 leandro-desktop dhclient: bound to 150.162.60.129 -- renewal in 9440 seconds.
Feb 23 13:17:02 leandro-desktop CRON[5546]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 23 14:17:01 leandro-desktop CRON[5552]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 23 14:56:42 leandro-desktop dhclient: DHCPREQUEST of 150.162.60.129 on eth0 to 150.162.60.5 port 67
Feb 23 14:56:42 leandro-desktop dhclient: DHCPACK of 150.162.60.129 from 150.162.60.5
Feb 23 14:56:42 leandro-desktop dhclient: bound to 150.162.60.129 -- renewal in 8640 seconds.
Feb 23 15:17:01 leandro-desktop CRON[5560]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 23 16:17:01 leandro-desktop CRON[5566]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 23 17:17:01 leandro-desktop CRON[5572]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 23 17:20:42 leandro-desktop dhclient: DHCPREQUEST of 150.162.60.129 on eth0 to 150.162.60.5 port 67
Feb 23 17:21:23 leandro-desktop dhclient: last message repeated 3 times
Feb 23 17:22:31 leandro-desktop dhclient: last message repeated 6 times

[[ muitas mensagens iguais a anterior]]

Feb 23 18:17:04 leandro-desktop dhclient: DHCPREQUEST of 150.162.60.129 on eth0 to 150.162.60.5 port 67
Feb 23 18:18:04 leandro-desktop dhclient: last message repeated 4 times

[[ muitas mensagens iguais a anterior]]

Feb 23 20:11:39 leandro-desktop dhclient: last message repeated 5 times
Feb 23 20:11:48 leandro-desktop dhclient: DHCPREQUEST of 150.162.60.129 on eth0 to 255.255.255.255 port 67
Feb 23 20:12:49 leandro-desktop dhclient: last message repeated 5 times
Feb 23 20:14:06 leandro-desktop dhclient: last message repeated 6 times
Feb 23 20:15:10 leandro-desktop dhclient: last message repeated 3 times
Feb 23 20:16:10 leandro-desktop dhclient: last message repeated 4 times
Feb 23 20:17:01 leandro-desktop dhclient: last message repeated 4 times
Feb 23 20:17:01 leandro-desktop CRON[5588]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 23 20:17:08 leandro-desktop dhclient: DHCPREQUEST of 150.162.60.129 on eth0 to 255.255.255.255 port 67
Feb 23 20:18:10 leandro-desktop dhclient: last message repeated 4 times

[[ muitas mensagens iguais a anterior]]

Feb 23 20:56:43 leandro-desktop dhclient: last message repeated 2 times
Feb 23 20:56:43 leandro-desktop NetworkManager: <info> DHCP: device eth0 state changed renew -> expire
Feb 23 20:56:43 leandro-desktop dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 7
Feb 23 20:56:43 leandro-desktop NetworkManager: <info> DHCP: device eth0 state changed expire -> preinit
Feb 23 20:56:50 leandro-desktop dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 12
Feb 23 20:57:02 leandro-desktop dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 20
Feb 23 20:57:22 leandro-desktop dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 17
Feb 23 20:57:39 leandro-desktop dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 5
Feb 23 20:57:44 leandro-desktop dhclient: No DHCPOFFERS received.
Feb 23 20:57:44 leandro-desktop dhclient: No working leases in persistent database - sleeping.
Feb 23 20:57:44 leandro-desktop NetworkManager: <info> DHCP: device eth0 state changed preinit -> fail
Feb 23 20:57:44 leandro-desktop NetworkManager: <info> (eth0): device state change: 8 -> 9 (reason 6)
Feb 23 20:57:44 leandro-desktop NetworkManager: <info> Activation (eth0) failed.
Feb 23 20:57:44 leandro-desktop NetworkManager: <info> (eth0): device state change: 9 -> 3 (reason 0)
Feb 23 20:57:44 leandro-desktop NetworkManager: <info> (eth0): deactivating device (reason: 0).
Feb 23 20:57:44 leandro-desktop NetworkManager: <info> (eth0): canceled DHCP transaction, dhcp client pid 780
Feb 23 20:57:44 leandro-desktop NetworkManager: <WARN> check_one_route(): (eth0) error -34 returned from rtnl_route_del(): Sucess#012
Feb 23 20:57:44 leandro-desktop avahi-daemon[761]: Withdrawing address record for 150.162.60.129 on eth0.
Feb 23 20:57:44 leandro-desktop avahi-daemon[761]: Leaving mDNS multicast group on interface eth0.IPv4 with address 150.162.60.129.
Feb 23 20:57:44 leandro-desktop avahi-daemon[761]: Interface eth0.IPv4 no longer relevant for mDNS.
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> Activation (eth0) starting connection 'Auto eth0'
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> (eth0): device state change: 3 -> 4 (reason 0)
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) scheduled...
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) started...
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> Activation (eth0) Stage 2 of 5 (Device Configure) scheduled...
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) complete.
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> Activation (eth0) Stage 2 of 5 (Device Configure) starting...
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> (eth0): device state change: 4 -> 5 (reason 0)
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> Activation (eth0) Stage 2 of 5 (Device Configure) successful.
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) scheduled.
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> Activation (eth0) Stage 2 of 5 (Device Configure) complete.
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) started...
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> (eth0): device state change: 5 -> 7 (reason 0)
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> Activation (eth0) Beginning DHCP transaction (timeout in 45 seconds)
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> dhclient started with pid 5608
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP6 Configure Get) scheduled...
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) complete.
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP6 Configure Get) started...
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP6 Configure Get) complete.
Feb 23 20:57:47 leandro-desktop dhclient: Internet Systems Consortium DHCP Client V3.1.3
Feb 23 20:57:47 leandro-desktop dhclient: Copyright 2004-2009 Internet Systems Consortium.
Feb 23 20:57:47 leandro-desktop dhclient: All rights reserved.
Feb 23 20:57:47 leandro-desktop dhclient: For info, please visit https://www.isc.org/software/dhcp/
Feb 23 20:57:47 leandro-desktop dhclient:
Feb 23 20:57:47 leandro-desktop NetworkManager: <info> DHCP: device eth0 state changed normal exit -> preinit
Feb 23 20:57:47 leandro-desktop dhclient: Listening on LPF/eth0/00:22:15:24:7b:a3
Feb 23 20:57:47 leandro-desktop dhclient: Sending on LPF/eth0/00:22:15:24:7b:a3
Feb 23 20:57:47 leandro-desktop dhclient: Sending on Socket/fallback
Feb 23 20:57:48 leandro-desktop dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 5
Feb 23 20:57:53 leandro-desktop dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 10
Feb 23 20:58:03 leandro-desktop dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 15
Feb 23 20:58:18 leandro-desktop dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 18
Feb 23 20:58:32 leandro-desktop NetworkManager: <info> (eth0): DHCP transaction took too long, stopping it.
Feb 23 20:58:32 leandro-desktop NetworkManager: <info> (eth0): canceled DHCP transaction, dhcp client pid 5608
Feb 23 20:58:32 leandro-desktop NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Timeout) scheduled...
Feb 23 20:58:32 leandro-desktop NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Timeout) started...
Feb 23 20:58:32 leandro-desktop NetworkManager: <info> (eth0): device state change: 7 -> 9 (reason 5)
Feb 23 20:58:32 leandro-desktop NetworkManager: <info> Marking connection 'Auto eth0' invalid.
Feb 23 20:58:32 leandro-desktop NetworkManager: <info> Activation (eth0) failed.
Feb 23 20:58:32 leandro-desktop NetworkManager: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Timeout) complete.
Feb 23 20:58:32 leandro-desktop NetworkManager: <info> (eth0): device state change: 9 -> 3 (reason 0)
Feb 23 20:58:32 leandro-desktop NetworkManager: <info> (eth0): deactivating device (reason: 0).

[zekkerj]

As primeiras mensagens são normais, dependendo do tempo que o servidor DHCP esteja concedendo o endereço.

O problema todo começa por volta das 17h, quando o cliente tenta renovar o endereço e não consegue resposta.

Antes de pensar em bug no dhclient, no entanto, é preciso descartar causas de hardware: cabo ruim (acontece muito), placa ruim, porta de switch ruim, switch ruim.

[leandrojk]

Concordo. Olhando as msgs abaixo

Feb 23 14:56:42 leandro-desktop dhclient: DHCPREQUEST of 150.162.60.129 on eth0 to 150.162.60.5 port 67
Feb 23 14:56:42 leandro-desktop dhclient: DHCPACK of 150.162.60.129 from 150.162.60.5
Feb 23 14:56:42 leandro-desktop dhclient: bound to 150.162.60.129 -- renewal in 8640 seconds.
Feb 23 15:17:01 leandro-desktop CRON[5560]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 23 16:17:01 leandro-desktop CRON[5566]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 23 17:17:01 leandro-desktop CRON[5572]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)
Feb 23 17:20:42 leandro-desktop dhclient: DHCPREQUEST of 150.162.60.129 on eth0 to 150.162.60.5 port 67
Feb 23 17:21:23 leandro-desktop dhclient: last message repeated 3 times
Feb 23 17:22:31 leandro-desktop dhclient: last message repeated 6 times

a minha dúvida é se é correto concluir que o problema é de hardware (cabo, placa de rede, etc) pois o comando DHCPREQUEST aparentemente para de funcionar a partir das 17:20:42 hs.

[zekkerj]

Não dá pra tirar conclusões sem testar. Há muitas variáveis que podem alterar esse resultado.