Gentoo Forums
Gentoo Forums
Gentoo Forums
Quick Search: in
dhclient: Timeout too large reducing to: (TIME_MAX - 1)
View unanswered posts
View posts from last 24 hours

 
Reply to topic    Gentoo Forums Forum Index Networking & Security
View previous topic :: View next topic  
Author Message
neyuru
Tux's lil' helper
Tux's lil' helper


Joined: 21 Mar 2020
Posts: 140

PostPosted: Sat Jun 27, 2020 1:35 am    Post subject: dhclient: Timeout too large reducing to: (TIME_MAX - 1) Reply with quote

I don't seem to have any problems with my networking but this is the only error left during boot-up:

Code:
dhclient[710]: Timeout too large reducing to: 2147483646 (TIME_MAX - 1)


A more comprehensive log:

journalctl -b 0 | grep -i 'networkmanager\|dhclient\|nm-dispatcher\|enp0s25\|timeout'
Code:
Jun 26 20:00:29 localhost kernel: nvme nvme0: Shutdown timeout set to 10 seconds
Jun 26 20:00:30 localhost kernel: e1000e 0000:00:19.0 enp0s25: renamed from eth0
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.6181] NetworkManager (version 1.18.6) is starting... (for the first time)
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.6188] Read config: /etc/NetworkManager/NetworkManager.conf (lib: 31-mac-addr-change.conf, iwd.conf)
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.6226] bus-manager: acquired D-Bus service "org.freedesktop.NetworkManager"
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.6236] manager[0x5565e3e6e0a0]: monitoring kernel firmware directory '/lib/firmware'.
Jun 26 20:00:31 localhost dbus-daemon[434]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.3' (uid=0 pid=435 comm="/usr/sbin/NetworkManager --no-daemon ")
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.8684] hostname: hostname: using hostnamed
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.8686] dns-mgr[0x5565e3e4e240]: init: dns=default,systemd-resolved rc-manager=symlink
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.8688] manager[0x5565e3e6e0a0]: rfkill: Wi-Fi hardware radio set enabled
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.8689] manager[0x5565e3e6e0a0]: rfkill: WWAN hardware radio set enabled
Jun 26 20:00:31 localhost dbus-daemon[434]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.3' (uid=0 pid=435 comm="/usr/sbin/NetworkManager --no-daemon ")
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.8867] settings: Loaded settings plugin: NMSKeyfilePlugin (internal)
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.8869] manager: rfkill: Wi-Fi enabled by radio killswitch; enabled by state file
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.8870] manager: rfkill: WWAN enabled by radio killswitch; enabled by state file
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.8871] manager: Networking is enabled by state file
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.8872] dhcp-init: Using DHCP client 'dhclient'
Jun 26 20:00:31 localhost nm-dispatcher[531]: req:1 'hostname': new request (1 scripts)
Jun 26 20:00:31 localhost nm-dispatcher[531]: req:1 'hostname': start running ordered scripts...
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.8885] Loaded device plugin: NMAtmManager (/usr/lib64/NetworkManager/1.18.6/libnm-device-plugin-adsl.so)
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.8915] Loaded device plugin: NMWwanFactory (/usr/lib64/NetworkManager/1.18.6/libnm-device-plugin-wwan.so)
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.8947] Loaded device plugin: NMTeamFactory (/usr/lib64/NetworkManager/1.18.6/libnm-device-plugin-team.so)
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.8967] Loaded device plugin: NMBluezManager (/usr/lib64/NetworkManager/1.18.6/libnm-device-plugin-bluetooth.so)
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.8975] Loaded device plugin: NMWifiFactory (/usr/lib64/NetworkManager/1.18.6/libnm-device-plugin-wifi.so)
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.8983] device (lo): carrier: link connected
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.8984] manager: (lo): new Generic device (/org/freedesktop/NetworkManager/Devices/1)
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.8991] manager: (enp0s25): new Ethernet device (/org/freedesktop/NetworkManager/Devices/2)
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.9011] keyfile: add connection /run/NetworkManager/system-connections/Wired connection 1.nmconnection (f9ef6815-f9b9-330f-80df-520d4c04bae8,"Wired connection 1")
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.9014] settings: (enp0s25): created default wired connection 'Wired connection 1'
Jun 26 20:00:31 localhost NetworkManager[435]: <info>  [1593219631.9019] device (enp0s25): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Jun 26 20:00:32 localhost nm-dispatcher[531]: req:2 'connectivity-change': new request (1 scripts)
Jun 26 20:00:32 localhost nm-dispatcher[531]: req:2 'connectivity-change': start running ordered scripts...
Jun 26 20:00:32 localhost NetworkManager[435]: <info>  [1593219632.0818] manager: (enp4s0): new Ethernet device (/org/freedesktop/NetworkManager/Devices/3)
Jun 26 20:00:32 localhost NetworkManager[435]: <info>  [1593219632.0827] keyfile: add connection /run/NetworkManager/system-connections/Wired connection 2.nmconnection (91240516-e272-324a-b4fc-026c4b4fe7f5,"Wired connection 2")
Jun 26 20:00:32 localhost NetworkManager[435]: <info>  [1593219632.0829] settings: (enp4s0): created default wired connection 'Wired connection 2'
Jun 26 20:00:32 localhost NetworkManager[435]: <info>  [1593219632.0833] device (enp4s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Jun 26 20:00:32 localhost NetworkManager[435]: <info>  [1593219632.1114] manager: (sit0): new IPTunnel device (/org/freedesktop/NetworkManager/Devices/4)
Jun 26 20:00:32 localhost dbus-daemon[434]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service' requested by ':1.3' (uid=0 pid=435 comm="/usr/sbin/NetworkManager --no-daemon ")
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0087] device (enp0s25): carrier: link connected
Jun 26 20:00:35 localhost kernel: e1000e: enp0s25 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: Rx/Tx
Jun 26 20:00:35 localhost kernel: IPv6: ADDRCONF(NETDEV_CHANGE): enp0s25: link becomes ready
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0089] device (enp0s25): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0095] policy: auto-activating connection 'Wired connection 1' (f9ef6815-f9b9-330f-80df-520d4c04bae8)
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0098] device (enp0s25): Activation: starting connection 'Wired connection 1' (f9ef6815-f9b9-330f-80df-520d4c04bae8)
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0099] device (enp0s25): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0102] manager: NetworkManager state is now CONNECTING
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0103] device (enp0s25): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0106] device (enp0s25): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0110] dhcp4 (enp0s25): activation: beginning transaction (timeout in 45 seconds)
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0230] dhcp4 (enp0s25): dhclient started with pid 710
Jun 26 20:00:35 localhost dhclient[710]: DHCPREQUEST for 192.168.0.100 on enp0s25 to 255.255.255.255 port 67
Jun 26 20:00:35 localhost dhclient[710]: DHCPACK of 192.168.0.100 from 192.168.0.1
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0474] dhcp4 (enp0s25):   address 192.168.0.100
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0474] dhcp4 (enp0s25):   plen 24 (255.255.255.0)
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0474] dhcp4 (enp0s25):   gateway 192.168.0.1
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0474] dhcp4 (enp0s25):   lease time 4294967295
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0474] dhcp4 (enp0s25):   nameserver '192.168.0.1'
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0474] dhcp4 (enp0s25): state changed unknown -> bound
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0481] device (enp0s25): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0487] device (enp0s25): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0489] device (enp0s25): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0492] manager: NetworkManager state is now CONNECTED_LOCAL
Jun 26 20:00:35 localhost dhclient[710]: Timeout too large reducing to: 2147483646 (TIME_MAX - 1)
Jun 26 20:00:35 localhost dhclient[710]: bound to 192.168.0.100 -- renewal in 2147483648 seconds.
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.1237] manager: NetworkManager state is now CONNECTED_SITE
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.1238] policy: set 'Wired connection 1' (enp0s25) as default for IPv4 routing and DNS
Jun 26 20:00:35 localhost dbus-daemon[434]: [system] Activating via systemd: service name='org.freedesktop.resolve1' unit='dbus-org.freedesktop.resolve1.service' requested by ':1.3' (uid=0 pid=435 comm="/usr/sbin/NetworkManager --no-daemon ")
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.1266] device (enp0s25): Activation: successful, device activated.
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.1271] manager: NetworkManager state is now CONNECTED_GLOBAL
Jun 26 20:00:35 localhost nm-dispatcher[531]: req:3 'up' [enp0s25]: new request (1 scripts)
Jun 26 20:00:35 localhost nm-dispatcher[531]: req:3 'up' [enp0s25]: start running ordered scripts...
Jun 26 20:00:35 localhost nm-dispatcher[531]: req:4 'connectivity-change': new request (1 scripts)
Jun 26 20:00:35 localhost nm-dispatcher[531]: req:4 'connectivity-change': start running ordered scripts...
Jun 26 20:00:37 localhost NetworkManager[435]: <info>  [1593219637.7442] dhcp6 (enp0s25): activation: beginning transaction (timeout in 45 seconds)
Jun 26 20:00:37 localhost NetworkManager[435]: <info>  [1593219637.7450] dhcp6 (enp0s25): dhclient started with pid 815
Jun 26 20:00:37 localhost NetworkManager[435]: <info>  [1593219637.7455] policy: set 'Wired connection 1' (enp0s25) as default for IPv6 routing and DNS
Jun 26 20:00:37 localhost dhclient[815]: XMT: Solicit on enp0s25, interval 1050ms.
Jun 26 20:00:38 localhost NetworkManager[435]: <info>  [1593219638.1113] manager: startup complete
Jun 26 20:00:38 localhost dhclient[815]: XMT: Solicit on enp0s25, interval 2030ms.
Jun 26 20:00:40 localhost NetworkManager[435]: <info>  [1593219640.0481] agent-manager: req[0x5565e3ef6680, :1.30/org.freedesktop.nm-applet/1000]: agent registered
Jun 26 20:00:40 localhost dhclient[815]: XMT: Solicit on enp0s25, interval 4110ms.
Jun 26 20:00:45 localhost dhclient[815]: XMT: Solicit on enp0s25, interval 8370ms.
Jun 26 20:00:45 localhost systemd[1]: NetworkManager-dispatcher.service: Succeeded.
Jun 26 20:00:53 localhost dhclient[815]: XMT: Solicit on enp0s25, interval 17100ms.
Jun 26 20:01:10 localhost dhclient[815]: XMT: Solicit on enp0s25, interval 34700ms.
Jun 26 20:01:22 localhost NetworkManager[435]: <warn>  [1593219682.7340] dhcp6 (enp0s25): request timed out
Jun 26 20:01:22 localhost NetworkManager[435]: <info>  [1593219682.7340] dhcp6 (enp0s25): state changed unknown -> timeout
Jun 26 20:01:22 localhost NetworkManager[435]: <info>  [1593219682.7348] dhcp6 (enp0s25): canceled DHCP transaction, DHCP client pid 815
Jun 26 20:01:22 localhost NetworkManager[435]: <info>  [1593219682.7348] dhcp6 (enp0s25): state changed timeout -> done


Can something be done to get rid of that error?

thanks!
Back to top
View user's profile Send private message
mike155
Advocate
Advocate


Joined: 17 Sep 2010
Posts: 2420
Location: Frankfurt, Germany

PostPosted: Sun Jun 28, 2020 12:37 am    Post subject: Reply with quote

It seems that your DHCP Server answers with a lease time of 4294967295s (=2^32-1)
Code:
dhcp4 (enp0s25): address 192.168.0.100
dhcp4 (enp0s25): plen 24 (255.255.255.0)
dhcp4 (enp0s25): gateway 192.168.0.1
dhcp4 (enp0s25): lease time 4294967295      <------
dhcp4 (enp0s25): nameserver '192.168.0.1'

Your DHCP client thinks that this number is too large. Therefore it reduces the lease time to 2147483646 (=2^31-2).

Change the configuration of your DHCP server. Reasonable values are generally between 3600 (1 hour) and 86400 (1 day).
Back to top
View user's profile Send private message
neyuru
Tux's lil' helper
Tux's lil' helper


Joined: 21 Mar 2020
Posts: 140

PostPosted: Sun Jun 28, 2020 5:51 am    Post subject: Reply with quote

Thanks! Although my router has a lease time of 2 hours (120 mins), maybe the problem lies in that I have configured it to give a fixed IP address to my computer. Maybe?
Back to top
View user's profile Send private message
Hu
Moderator
Moderator


Joined: 06 Mar 2007
Posts: 15989

PostPosted: Sun Jun 28, 2020 4:40 pm    Post subject: Reply with quote

When you say your router has a lease time of 2 hours, do you mean that it gets a 2 hour lease from your ISP for the public IP that your router will use on the Internet, or do you mean that the DHCP server on your router issues 2 hour leases to clients on your LAN? It's possible that your router's DHCP server decided to override the lease duration because of how you configured it to issue the address. I am not aware of any Linux-based DHCP daemons that would do that, but if this is some embedded vendor DHCP daemon, the vendor might have done (or found) something strange.
Back to top
View user's profile Send private message
neyuru
Tux's lil' helper
Tux's lil' helper


Joined: 21 Mar 2020
Posts: 140

PostPosted: Sun Jun 28, 2020 5:30 pm    Post subject: Reply with quote

Hu wrote:
When you say your router has a lease time of 2 hours, do you mean that it gets a 2 hour lease from your ISP for the public IP that your router will use on the Internet, or do you mean that the DHCP server on your router issues 2 hour leases to clients on your LAN?


I think it's the time the router leases to the PC. From the router's configuration webpage:

Quote:
Lease Time - The Address Lease Time is the length of time a network user will be allowed to keep connecting to the Router with the current DHCP Address. Enter the amount of time, in minutes, that the DHCP address will be "leased". The time range is 1~2880 minutes. The default value is 120 minutes.


I have disabled the address reservation for the PC's MAC address and now the error is gone.

Quote:
Address Reservation Help

When you specify a reserved IP address for a PC in the LAN, that PC will always receive the same IP address each time when it accesses the DHCP server. Reserved IP addresses could be assigned to servers that require permanent IP settings.


I assume then this error is has no important consequences? Can I safely revert back the permanent leasing to the PC? Did I miss some configuration on the PC end to let know linux that the IP address is permanent? or... would this case be worthy to report to the appropriate maintaner/dev to take this case into account?
Back to top
View user's profile Send private message
Hu
Moderator
Moderator


Joined: 06 Mar 2007
Posts: 15989

PostPosted: Sun Jun 28, 2020 7:38 pm    Post subject: Reply with quote

neyuru wrote:
I assume then this error is has no important consequences? Can I safely revert back the permanent leasing to the PC? Did I miss some configuration on the PC end to let know linux that the IP address is permanent? or... would this case be worthy to report to the appropriate maintaner/dev to take this case into account?
I cannot say whether it has important consequences, but I cannot see any based on what you have showed. A permanent lease should be fine, if you do not mind the diagnostic message. No, you did not miss any configuration on Linux. Typically, reservations like this ensure a fixed MAC <-> IP mapping and may grant some extra duration (say, 7 days instead of 6 hours). I have not seen a daemon that explicitly makes the reservation good until the end of time.

You could try reporting this as a defect to the developer of the DHCP server on the router, since some DHCP clients may actually misbehave in the presence of such an excessive lease. Additionally, even if clients do not misbehave directly, issuing a multi-year lease may interfere with adjusting the DHCP parameters later, since the client would rightfully believe that it does not need to talk to the server for the next several years, so it may not pick up changes from the server, such as a change of DNS servers. For these reasons, it is traditional that a reservation guarantee an IP address, but not last for more than a couple of weeks.
Back to top
View user's profile Send private message
UberLord
Retired Dev
Retired Dev


Joined: 18 Sep 2003
Posts: 6799
Location: Blighty

PostPosted: Sun Jun 28, 2020 9:50 pm    Post subject: Reply with quote

4294967295 is the maximum uint32_t value, which in DHCP, DHCPv6 and RA parlance means infinite.
So basically it should not expire. Looks like a bug in dhclient.
_________________
Use dhcpcd for all your automated network configuration needs
Use dhcpcd-ui (GTK+/Qt) as your System Tray Network tool
Back to top
View user's profile Send private message
neyuru
Tux's lil' helper
Tux's lil' helper


Joined: 21 Mar 2020
Posts: 140

PostPosted: Tue Jun 30, 2020 5:08 am    Post subject: Reply with quote

mmmm... so, the router sends:

Code:
Jun 26 20:00:35 localhost NetworkManager[435]: <info>  [1593219635.0474] dhcp4 (enp0s25):   lease time 4294967295


but the client does not accept this number, so it changes it to:

Code:
Jun 26 20:00:35 localhost dhclient[710]: Timeout too large reducing to: 2147483646 (TIME_MAX - 1)


and it will try to request another IP in ~68 years:

Code:
Jun 26 20:00:35 localhost dhclient[710]: bound to 192.168.0.100 -- renewal in 2147483648 seconds.


I guess I shouldn't worry, and I guess this is the current limitation (32 bit int) of the implementation... any thoughts?
Back to top
View user's profile Send private message
Display posts from previous:   
Reply to topic    Gentoo Forums Forum Index Networking & Security All times are GMT
Page 1 of 1

 
Jump to:  
You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum