Core 141 dhcp red breaking red interface

Networking
1

It looks like every time my lease expires, the red interface goes away. When the red interface goes away my IPSec VPN goes away. WTF??

Feb 27 12:59:35 ipfire dhcpcd[14578]: red0: DHCP lease expired
Feb 27 12:59:35 ipfire dhcpcd[14578]: red0: deleting route to 71.233.112.0/21
Feb 27 12:59:35 ipfire dhcpcd[14578]: red0: deleting default route via 71.233.112.1
Feb 27 12:59:35 ipfire charon: 09[KNL] 71.233.115.176 disappeared from red0 
Feb 27 12:59:35 ipfire dhcpcd.exe[15264]: red0 has been brought down (EXPIRE)
Feb 27 12:59:35 ipfire unbound: [13567:0] info: service stopped (unbound 1.9.6).
Feb 27 12:59:35 ipfire unbound: [13567:0] info: server stats for thread 0: 1558 queries, 193 answers from cache, 1365 recursions, 22 prefetch, 0 rejected by ip ratelimiting
Feb 27 12:59:35 ipfire unbound: [13567:0] info: server stats for thread 0: requestlist max 11 avg 0.766402 exceeded 0 jostled 0
2

I find that my ISP router is slow to respond to DHCP requests and that can result in IPFire moving on before the red interface comes up.

My solution is to set red to “static”. It does require also defining DNS & Gateway in IPFire setup.

3

I will try that but I think something else is wrong. lease expires, solicits a lease, ignores offer, then gets lease somehow, and rebuilds red interface. this is not right behavior. a dhcp lease should remain valid for 2x TTL and the interface plus routes should remain in place just in case the DHCP server is slow or network is lossy.

1 Like
4

Fixed IP will work. Do you have the option to change the lease time of the router/modems DHCP?

5

no. the lease time is set by comcast. I have my own cable modem. I was looking in my logs and the DHCPCD behavior changed about 3-4 weeks ago. since I was not paying attention, I’m not sure if it is related to an IPFire update.

Main problem is Comcast changes my IP address every 3-4 months and now I have no way to detect it. The right answer it to figure out if it is dhcpcd or comcast (either general network forkery or 3ed party modem forkery).

fwiw, comcast will rent me a single static address for 20$/month only if I use their cable modem for another 15$ a month. forken bandits.

note on switching to static. I got a bunch of rrd and iptable failures. cleaned out the rrd directory, the problems went away and it seems to be working right.

6

BFH, the static IP config worked for about an hour. then it stopped. could comcast shutoff your address if you are not grabbing a dhcp address?

in anycase, now both IPSec tunnels are down. I really hate IPSec…

7

So we are talking about a public IP on RED? In my opinion the behaviour is normal and ipfire can’t do anything about it. Whenever a route is not valid anymore it needs to be removed.

The question is: does it come back by it’s own with the new IP on RED?

8

yes, we are talking about a public IP on red. dhcp supplied address from Comcast.

it is normal to remove a route if an address goes away (exceeds DHCP TTL) BUT a simple renewal should not make the address go away. I now need to back up 1 release to 139 and see if it is a new problem from IPFire or Comcast. Both have changed lately.

9

I had a similar problem on my fiber. I have a fixed IP, but it is dished out via DHCP from the provider. I managed to solve my problem by fixing the MTU to 1500 on RED in the setup. Frankly, I still don’t know exactly what the problem is, but this did the trick in my case. No guarantees, but might be worth a try.

BTW: I also suspected ipfire at first. DHCP used to work for years without fixing the MTU, but all of a sudden this problem appeared. I my case it coincided with the ipfire update from 138 to 139, but really I don’t think ipfire is the culprit in my case.

10

interesting, the MTU defaults to 1500. how did you set the MTU in your case?

11

I suspect that in my case the ISP is trying to set a different MTU via DHCP and that fails, causing it to loose the connection. The connection then breaks and a fresh connection is set up - and repeat the cycle.
You can set the MTU on RED in the setup program of the ipfire. With putty, SSH into the ipfire, login as root and execute the command “setup”. This is the same setup-routine as in the first install. Then choose “networking”, “address settings” and “Interface RED”. There you have the option “Force DHCP MTU” - set it to 1500.
P.S. Don’t forget to enable SSH in the web-console first. Alternatively, you can use the console direct (serial or otherwise).

Good luck!

12

thanks, I forced the MTU to 1500 as you suggested. lets see of the connection is stable for over 3956 seconds.

13

nope. it failed again. here is log of dhcpcd plus a bunch of related log data dhcpcd should not be removing the red interface. Doing so breaks all VPNs and any persistent traffic across the red interface.

 Mar 4 12:01:08 ipfire dhcpcd[21858]: sending signal ALRM to pid 14290
Mar  4 12:01:08 ipfire dhcpcd[21858]: waiting for pid 14290 to exit
Mar  4 12:01:08 ipfire dhcpcd[14290]: received SIGALRM, releasing
Mar  4 12:01:08 ipfire dhcpcd[14290]: red0: removing interface
Mar  4 12:01:08 ipfire dhcpcd[14290]: red0: releasing lease of 71.233.118.65
Mar  4 12:01:08 ipfire dhcpcd[14290]: red0: deleting route to 71.233.112.0/21
Mar  4 12:01:08 ipfire dhcpcd[14290]: red0: deleting default route via 71.233.112.1
Mar  4 12:01:08 ipfire dhcpcd.exe[21859]: red0 has been brought down (STOP)
Mar  4 12:01:08 ipfire unbound: [13526:0] info: service stopped (unbound 1.9.6).
Mar  4 12:01:08 ipfire unbound: [13526:0] info: server stats for thread 0: 343 queries, 37 answers from cache, 306 recursions, 2 prefetch, 0 rejected by ip ratelimiting
Mar  4 12:01:08 ipfire unbound: [13526:0] info: server stats for thread 0: requestlist max 5 avg 0.451299 exceeded 0 jostled 0
Mar  4 12:01:08 ipfire unbound: [13526:0] info: average recursion processing time 0.044298 sec
Mar  4 12:01:08 ipfire unbound: [13526:0] info: histogram of recursion processing times
Mar  4 12:01:08 ipfire unbound: [13526:0] info: [25%]=0.0102666 median[50%]=0.0215723 [75%]=0.0575183
Mar  4 12:01:08 ipfire unbound: [13526:0] info: lower(secs) upper(secs) recursions
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.000000    0.000001 36
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.000128    0.000256 1
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.001024    0.002048 1
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.002048    0.004096 3
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.004096    0.008192 16
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.008192    0.016384 77
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.016384    0.032768 60
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.032768    0.065536 47
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.065536    0.131072 45
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.131072    0.262144 17
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.262144    0.524288 1
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.524288    1.000000 1
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    1.000000    2.000000 1
Mar  4 12:01:08 ipfire unbound: [13526:0] info: server stats for thread 1: 402 queries, 50 answers from cache, 352 recursions, 5 prefetch, 0 rejected by ip ratelimiting
Mar  4 12:01:08 ipfire unbound: [13526:0] info: server stats for thread 1: requestlist max 8 avg 0.579832 exceeded 0 jostled 0
Mar  4 12:01:08 ipfire unbound: [13526:0] info: average recursion processing time 0.039861 sec
Mar  4 12:01:08 ipfire unbound: [13526:0] info: histogram of recursion processing times
Mar  4 12:01:08 ipfire unbound: [13526:0] info: [25%]=0.0103975 median[50%]=0.0233416 [75%]=0.0534163
Mar  4 12:01:08 ipfire unbound: [13526:0] info: lower(secs) upper(secs) recursions
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.000000    0.000001 37
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.000128    0.000256 1
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.001024    0.002048 2
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.002048    0.004096 8
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.004096    0.008192 19
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.008192    0.016384 78
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.016384    0.032768 73
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.032768    0.065536 73
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.065536    0.131072 40
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.131072    0.262144 18
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.262144    0.524288 1
Mar  4 12:01:08 ipfire unbound: [13526:0] info:    0.524288    1.000000 2
Mar  4 12:01:08 ipfire unbound: [13526:0] notice: Restart of unbound 1.9.6.
Mar  4 12:01:08 ipfire unbound: [13526:0] notice: init module 0: validator
Mar  4 12:01:08 ipfire unbound: [13526:0] notice: init module 1: iterator
Mar  4 12:01:08 ipfire unbound: [13526:0] info: start of service (unbound 1.9.6).
Mar  4 12:01:08 ipfire unbound: [13526:0] info: service stopped (unbound 1.9.6).
Mar  4 12:01:08 ipfire unbound: [13526:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar  4 12:01:08 ipfire unbound: [13526:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar  4 12:01:08 ipfire unbound: [13526:0] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar  4 12:01:08 ipfire unbound: [13526:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar  4 12:01:08 ipfire unbound: [13526:0] notice: Restart of unbound 1.9.6.
Mar  4 12:01:08 ipfire unbound: [13526:0] notice: init module 0: validator
Mar  4 12:01:08 ipfire unbound: [13526:0] notice: init module 1: iterator
Mar  4 12:01:08 ipfire unbound: [13526:0] info: start of service (unbound 1.9.6).
Mar  4 12:01:08 ipfire openvpnserver[14200]: event_wait : Interrupted system call (code=4)
Mar  4 12:01:08 ipfire openvpnserver[14200]: /sbin/ip route del 10.115.104.0/24
Mar  4 12:01:08 ipfire openvpnserver[14200]: ERROR: Linux route delete command failed: external program exited with error status: 2
Mar  4 12:01:08 ipfire openvpnserver[14200]: Closing TUN/TAP interface
Mar  4 12:01:08 ipfire openvpnserver[14200]: /sbin/ip addr del dev tun0 local 10.115.104.1 peer 10.115.104.2
Mar  4 12:01:08 ipfire openvpnserver[14200]: Linux ip addr del failed: external program exited with error status: 2
Mar  4 12:01:08 ipfire openvpnserver[14200]: SIGTERM[hard,] received, process exiting
Mar  4 12:01:08 ipfire ipsec_starter[14176]: ipsec starter stopped
Mar  4 12:01:08 ipfire ipsec: Creating route to 192.168.9.0/255.255.255.0 (via 192.168.20.1 and red0)
Mar  4 12:01:08 ipfire ipsec: Creating route to 192.168.101.0/255.255.255.0 (via 192.168.20.1 and red0)
Mar  4 12:01:08 ipfire dhcpcd[14290]: dhcpcd exited
Mar  4 12:01:08 ipfire kernel: r8169 0000:04:00.0 red0: link down
Mar  4 12:01:08 ipfire kernel: r8169 0000:04:00.0 red0: link down
Mar  4 12:01:09 ipfire dhcpcd[22234]: DUID 00:04:4c:4c:45:44:00:31:58:10:80:30:c7:c0:4f:4d:53:31
Mar  4 12:01:09 ipfire dhcpcd[22234]: red0: IAID e5:19:be:83
Mar  4 12:01:09 ipfire dhcpcd[22234]: red0: adding address fe80::d267:e5ff:fe19:be83
Mar  4 12:01:09 ipfire dhcpcd[22234]: ipv6_addaddr1: Permission denied
Mar  4 12:01:09 ipfire dhcpcd[22234]: red0: carrier lost
Mar  4 12:01:11 ipfire dhcpcd[22234]: red0: carrier acquired
Mar  4 12:01:11 ipfire kernel: r8169 0000:04:00.0 red0: link up
Mar  4 12:01:11 ipfire dhcpcd[22234]: red0: IAID e5:19:be:83
Mar  4 12:01:11 ipfire dhcpcd[22234]: red0: soliciting an IPv6 router
Mar  4 12:01:12 ipfire dhcpcd[22234]: red0: soliciting a DHCP lease
Mar  4 12:01:12 ipfire dhcpcd[22234]: red0: offered 71.233.118.65 from 69.252.65.198
Mar  4 12:01:12 ipfire dhcpcd[22234]: red0: ignoring offer of 71.233.118.65 from 69.252.65.198
Mar  4 12:01:12 ipfire dhcpcd[22234]: red0: probing address 71.233.118.65/21
Mar  4 12:01:17 ipfire dhcpcd[22234]: red0: leased 71.233.118.65 for 3956 seconds
Mar  4 12:01:17 ipfire dhcpcd[22234]: red0: adding route to 71.233.112.0/21
Mar  4 12:01:17 ipfire dhcpcd[22234]: red0: adding default route via 71.233.112.1
Mar  4 12:01:17 ipfire dhcpcd.exe[22298]: red0 has been (re)configured with IP=71.233.118.65
Mar  4 12:01:18 ipfire unbound: [13526:0] info: service stopped (unbound 1.9.6).
Mar  4 12:01:18 ipfire unbound: [13526:0] info: server stats for thread 0: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar  4 12:01:18 ipfire unbound: [13526:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar  4 12:01:18 ipfire unbound: [13526:0] info: average recursion processing time 0.000000 sec
Mar  4 12:01:18 ipfire unbound: [13526:0] info: histogram of recursion processing times
Mar  4 12:01:18 ipfire unbound: [13526:0] info: [25%]=0 median[50%]=0 [75%]=0
Mar  4 12:01:18 ipfire unbound: [13526:0] info: lower(secs) upper(secs) recursions
Mar  4 12:01:18 ipfire unbound: [13526:0] info:    0.000000    0.000001 1
Mar  4 12:01:18 ipfire unbound: [13526:0] info: server stats for thread 1: 1 queries, 1 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar  4 12:01:18 ipfire unbound: [13526:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar  4 12:01:18 ipfire unbound: [13526:0] notice: Restart of unbound 1.9.6.
Mar  4 12:01:18 ipfire unbound: [13526:0] notice: init module 0: validator
Mar  4 12:01:18 ipfire unbound: [13526:0] notice: init module 1: iterator
Mar  4 12:01:18 ipfire unbound: [13526:0] info: start of service (unbound 1.9.6).
Mar  4 12:01:18 ipfire ntpd[14436]: Listen normally on 6 red0 71.233.118.65:123
Mar  4 12:01:18 ipfire ntpd[14436]: new interface(s) found: waking up resolver
Mar  4 12:01:19 ipfire unbound: [13526:0] info: generate keytag query _ta-4a5c-4f66. NULL IN
Mar  4 12:01:25 ipfire ipsec: Creating route to 192.168.9.0/255.255.255.0 (via 192.168.20.1 and red0)
Mar  4 12:01:25 ipfire ipsec: Creating route to 192.168.101.0/255.255.255.0 (via 192.168.20.1 and red0)
Mar  4 12:01:27 ipfire ipsec_starter[22782]: Starting strongSwan 5.8.1 IPsec [starter]...
Mar  4 12:01:27 ipfire openvpnserver[22835]: OpenVPN 2.4.8 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on Dec 14 2019
Mar  4 12:01:27 ipfire openvpnserver[22835]: library versions: OpenSSL 1.1.1d  10 Sep 2019, LZO 2.09
Mar  4 12:01:27 ipfire openvpnserver[22836]: WARNING: --keepalive option is missing from server config
Mar  4 12:01:27 ipfire openvpnserver[22836]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Mar  4 12:01:27 ipfire openvpnserver[22836]: Diffie-Hellman initialized with 2048 bit key
Mar  4 12:01:27 ipfire openvpnserver[22836]: Failed to extract curve from certificate (UNDEF), using secp384r1 instead.
Mar  4 12:01:27 ipfire openvpnserver[22836]: ECDH curve secp384r1 added
Mar  4 12:01:27 ipfire openvpnserver[22836]: WARNING: normally if you use --mssfix and/or --fragment, you should also set --tun-mtu 1500 (currently it is 1400)
Mar  4 12:01:27 ipfire openvpnserver[22836]: ROUTE_GATEWAY 71.233.112.1/255.255.248.0 IFACE=red0 HWADDR=d0:67:e5:19:be:83
Mar  4 12:01:27 ipfire openvpnserver[22836]: TUN/TAP device tun0 opened
Mar  4 12:01:27 ipfire openvpnserver[22836]: TUN/TAP TX queue length set to 100
Mar  4 12:01:27 ipfire openvpnserver[22836]: /sbin/ip link set dev tun0 up mtu 1400
Mar  4 12:01:27 ipfire openvpnserver[22836]: /sbin/ip addr add dev tun0 local 10.115.104.1 peer 10.115.104.2
Mar  4 12:01:27 ipfire openvpnserver[22836]: /sbin/ip route add 10.115.104.0/24 via 10.115.104.2
Mar  4 12:01:27 ipfire openvpnserver[22836]: Could not determine IPv4/IPv6 protocol. Using AF_INET
Mar  4 12:01:27 ipfire openvpnserver[22836]: Socket Buffers: R=[212992->212992] S=[212992->212992]
Mar  4 12:01:27 ipfire openvpnserver[22836]: UDPv4 link local (bound): [AF_INET][undef]:1194
Mar  4 12:01:27 ipfire openvpnserver[22836]: UDPv4 link remote: [AF_UNSPEC]
Mar  4 12:01:27 ipfire openvpnserver[22836]: GID set to nobody
Mar  4 12:01:27 ipfire openvpnserver[22836]: UID set to nobody
Mar  4 12:01:27 ipfire openvpnserver[22836]: MULTI: multi_init called, r=256 v=256
Mar  4 12:01:27 ipfire openvpnserver[22836]: IFCONFIG POOL: base=10.115.104.4 size=62, ipv6=0
Mar  4 12:01:27 ipfire openvpnserver[22836]: ifconfig_pool_read(), in='es5rv,10.115.104.4', TODO: IPv6
Mar  4 12:01:27 ipfire openvpnserver[22836]: succeeded -> ifconfig_pool_set()
Mar  4 12:01:27 ipfire openvpnserver[22836]: IFCONFIG POOL LIST
Mar  4 12:01:27 ipfire openvpnserver[22836]: es5rv,10.115.104.4
Mar  4 12:01:27 ipfire openvpnserver[22836]: Initialization Sequence Completed
Mar  4 12:01:27 ipfire codel: Codel AQM has been enabled on 'tun0'.
Mar  4 12:01:27 ipfire dhcpcd[22234]: forked to background, child pid 22910
Mar  4 12:01:27 ipfire ipsec: Creating route to 192.168.9.0/255.255.255.0 (via 192.168.20.1 and red0)
Mar  4 12:01:27 ipfire ipsec: Creating route to 192.168.101.0/255.255.255.0 (via 192.168.20.1 and red0)
Mar  4 12:01:27 ipfire unbound: [13526:0] info: service stopped (unbound 1.9.6).
Mar  4 12:01:27 ipfire unbound: [13526:0] info: server stats for thread 0: 2 queries, 1 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar  4 12:01:27 ipfire unbound: [13526:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar  4 12:01:27 ipfire unbound: [13526:0] info: average recursion processing time 1.056147 sec
Mar  4 12:01:27 ipfire unbound: [13526:0] info: histogram of recursion processing times
Mar  4 12:01:27 ipfire unbound: [13526:0] info: [25%]=0 median[50%]=0 [75%]=0
Mar  4 12:01:27 ipfire unbound: [13526:0] info: lower(secs) upper(secs) recursions
Mar  4 12:01:27 ipfire unbound: [13526:0] info:    1.000000    2.000000 1
Mar  4 12:01:27 ipfire unbound: [13526:0] info: server stats for thread 1: 4 queries, 0 answers from cache, 4 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar  4 12:01:27 ipfire unbound: [13526:0] info: server stats for thread 1: requestlist max 2 avg 0.5 exceeded 0 jostled 0
Mar  4 12:01:27 ipfire unbound: [13526:0] info: average recursion processing time 0.065650 sec
Mar  4 12:01:27 ipfire unbound: [13526:0] info: histogram of recursion processing times
Mar  4 12:01:27 ipfire unbound: [13526:0] info: [25%]=1e-06 median[50%]=0.065536 [75%]=0.098304
Mar  4 12:01:27 ipfire unbound: [13526:0] info: lower(secs) upper(secs) recursions
Mar  4 12:01:27 ipfire unbound: [13526:0] info:    0.000000    0.000001 1
Mar  4 12:01:27 ipfire unbound: [13526:0] info:    0.032768    0.065536 1
Mar  4 12:01:27 ipfire unbound: [13526:0] info:    0.065536    0.131072 2
Mar  4 12:01:28 ipfire ntpd[14436]: Listen normally on 7 tun0 10.115.104.1:123
Mar  4 12:01:28 ipfire ntpd[14436]: new interface(s) found: waking up resolver
Mar  4 12:01:29 ipfire unbound: [23061:0] notice: init module 0: validator
Mar  4 12:01:29 ipfire unbound: [23061:0] notice: init module 1: iterator
Mar  4 12:01:29 ipfire unbound: [23061:0] info: start of service (unbound 1.9.6).
Mar  4 12:01:42 ipfire unbound: [23061:1] info: generate keytag query _ta-4a5c-4f66. NULL IN
Mar  4 12:27:30 ipfire last message repeated 3 times
Mar  4 12:28:31 ipfire last message repeated 2 times
Mar  4 12:30:23 ipfire last message repeated 5 times
Mar  4 12:32:15 ipfire last message repeated 2 times
Mar  4 12:58:58 ipfire dhcpcd[22910]: red0: failed to renew DHCP, rebinding
Mar  4 12:58:58 ipfire dhcpcd[22910]: red0: truncated packet (128) from 192.168.20.1
Mar  4 13:00:03 ipfire last message repeated 5 times
Mar  4 13:01:24 ipfire unbound: [23061:0] info: generate keytag query _ta-4a5c-4f66. NULL IN
Mar  4 13:07:13 ipfire dhcpcd[22910]: red0: DHCP lease expired
Mar  4 13:07:13 ipfire dhcpcd[22910]: red0: deleting route to 71.233.112.0/21
Mar  4 13:07:13 ipfire dhcpcd[22910]: red0: deleting default route via 71.233.112.1
Mar  4 13:07:13 ipfire dhcpcd.exe[1381]: red0 has been brought down (EXPIRE)
Mar  4 13:07:13 ipfire unbound: [23061:0] info: service stopped (unbound 1.9.6).
Mar  4 13:07:13 ipfire unbound: [23061:0] info: server stats for thread 0: 610 queries, 72 answers from cache, 538 recursions, 1 prefetch, 0 rejected by ip ratelimiting
Mar  4 13:07:13 ipfire unbound: [23061:0] info: server stats for thread 0: requestlist max 5 avg 0.372913 exceeded 0 jostled 0
Mar  4 13:07:13 ipfire unbound: [23061:0] info: average recursion processing time 0.036175 sec
Mar  4 13:07:13 ipfire unbound: [23061:0] info: histogram of recursion processing times
Mar  4 13:07:13 ipfire unbound: [23061:0] info: [25%]=0.00926989 median[50%]=0.0191147 [75%]=0.0497987
Mar  4 13:07:13 ipfire unbound: [23061:0] info: lower(secs) upper(secs) recursions
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.000000    0.000001 70
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.000128    0.000256 1
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.000512    0.001024 2
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.001024    0.002048 6
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.002048    0.004096 5
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.004096    0.008192 33
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.008192    0.016384 133
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.016384    0.032768 114
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.032768    0.065536 76
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.065536    0.131072 76
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.131072    0.262144 18
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.262144    0.524288 4
Mar  4 13:07:13 ipfire unbound: [23061:0] info: server stats for thread 1: 646 queries, 106 answers from cache, 540 recursions, 10 prefetch, 0 rejected by ip ratelimiting
Mar  4 13:07:13 ipfire unbound: [23061:0] info: server stats for thread 1: requestlist max 5 avg 0.390909 exceeded 0 jostled 0
Mar  4 13:07:13 ipfire unbound: [23061:0] info: average recursion processing time 0.032798 sec
Mar  4 13:07:13 ipfire unbound: [23061:0] info: histogram of recursion processing times
Mar  4 13:07:13 ipfire unbound: [23061:0] info: [25%]=0.0094208 median[50%]=0.0186245 [75%]=0.045011
Mar  4 13:07:13 ipfire unbound: [23061:0] info: lower(secs) upper(secs) recursions
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.000000    0.000001 74
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.000512    0.001024 2
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.001024    0.002048 1
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.002048    0.004096 7
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.004096    0.008192 30
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.008192    0.016384 140
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.016384    0.032768 117
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.032768    0.065536 91
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.065536    0.131072 63
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.131072    0.262144 10
Mar  4 13:07:13 ipfire unbound: [23061:0] info:    0.262144    0.524288 5
Mar  4 13:07:13 ipfire unbound: [23061:0] notice: Restart of unbound 1.9.6.
Mar  4 13:07:13 ipfire unbound: [23061:0] notice: init module 0: validator
Mar  4 13:07:13 ipfire unbound: [23061:0] notice: init module 1: iterator
Mar  4 13:07:13 ipfire unbound: [23061:0] info: start of service (unbound 1.9.6).
Mar  4 13:07:13 ipfire unbound: [23061:0] info: service stopped (unbound 1.9.6).
Mar  4 13:07:13 ipfire unbound: [23061:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar  4 13:07:13 ipfire unbound: [23061:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar  4 13:07:13 ipfire unbound: [23061:0] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar  4 13:07:13 ipfire unbound: [23061:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar  4 13:07:13 ipfire unbound: [23061:0] notice: Restart of unbound 1.9.6.
Mar  4 13:07:13 ipfire unbound: [23061:0] notice: init module 0: validator
Mar  4 13:07:13 ipfire unbound: [23061:0] notice: init module 1: iterator
Mar  4 13:07:13 ipfire unbound: [23061:0] info: start of service (unbound 1.9.6).
Mar  4 13:07:13 ipfire openvpnserver[22836]: event_wait : Interrupted system call (code=4)
Mar  4 13:07:13 ipfire openvpnserver[22836]: /sbin/ip route del 10.115.104.0/24
Mar  4 13:07:13 ipfire openvpnserver[22836]: ERROR: Linux route delete command failed: external program exited with error status: 2
Mar  4 13:07:13 ipfire openvpnserver[22836]: Closing TUN/TAP interface
Mar  4 13:07:13 ipfire openvpnserver[22836]: /sbin/ip addr del dev tun0 local 10.115.104.1 peer 10.115.104.2
Mar  4 13:07:13 ipfire openvpnserver[22836]: Linux ip addr del failed: external program exited with error status: 2
Mar  4 13:07:13 ipfire openvpnserver[22836]: SIGTERM[hard,] received, process exiting
Mar  4 13:07:13 ipfire ipsec_starter[22798]: ipsec starter stopped
Mar  4 13:07:13 ipfire ipsec: Creating route to 192.168.9.0/255.255.255.0 (via 192.168.20.1 and red0)
Mar  4 13:07:13 ipfire ipsec: Creating route to 192.168.101.0/255.255.255.0 (via 192.168.20.1 and red0)
Mar  4 13:07:13 ipfire dhcpcd[22910]: red0: soliciting a DHCP lease
Mar  4 13:07:13 ipfire dhcpcd[22910]: red0: offered 71.233.118.65 from 69.252.65.198
Mar  4 13:07:13 ipfire dhcpcd[22910]: red0: ignoring offer of 71.233.118.65 from 69.252.65.198
Mar  4 13:07:14 ipfire dhcpcd[22910]: red0: probing address 71.233.118.65/21
Mar  4 13:07:18 ipfire dhcpcd[22910]: red0: leased 71.233.118.65 for 5221 seconds
Mar  4 13:07:18 ipfire dhcpcd[22910]: red0: adding route to 71.233.112.0/21
Mar  4 13:07:18 ipfire dhcpcd[22910]: red0: adding default route via 71.233.112.1
Mar  4 13:07:18 ipfire dhcpcd.exe[1655]: red0 has been (re)configured with IP=71.233.118.65
Mar  4 13:07:19 ipfire unbound: [23061:0] info: service stopped (unbound 1.9.6).
Mar  4 13:07:19 ipfire unbound: [23061:0] info: server stats for thread 0: 2 queries, 1 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar  4 13:07:19 ipfire unbound: [23061:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar  4 13:07:19 ipfire unbound: [23061:0] info: average recursion processing time 0.000000 sec
Mar  4 13:07:19 ipfire unbound: [23061:0] info: histogram of recursion processing times
Mar  4 13:07:19 ipfire unbound: [23061:0] info: [25%]=0 median[50%]=0 [75%]=0
Mar  4 13:07:19 ipfire unbound: [23061:0] info: lower(secs) upper(secs) recursions
Mar  4 13:07:19 ipfire unbound: [23061:0] info:    0.000000    0.000001 1
Mar  4 13:07:19 ipfire unbound: [23061:0] info: server stats for thread 1: 1 queries, 0 answers from cache, 1 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar  4 13:07:19 ipfire unbound: [23061:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar  4 13:07:19 ipfire unbound: [23061:0] info: average recursion processing time 0.000000 sec
Mar  4 13:07:19 ipfire unbound: [23061:0] info: histogram of recursion processing times
Mar  4 13:07:19 ipfire unbound: [23061:0] info: [25%]=0 median[50%]=0 [75%]=0
Mar  4 13:07:19 ipfire unbound: [23061:0] info: lower(secs) upper(secs) recursions
Mar  4 13:07:19 ipfire unbound: [23061:0] info:    0.000000    0.000001 1
Mar  4 13:07:19 ipfire unbound: [23061:0] notice: Restart of unbound 1.9.6.
Mar  4 13:07:19 ipfire unbound: [23061:0] notice: init module 0: validator
Mar  4 13:07:19 ipfire unbound: [23061:0] notice: init module 1: iterator
Mar  4 13:07:19 ipfire unbound: [23061:0] info: start of service (unbound 1.9.6).
Mar  4 13:07:19 ipfire unbound: [23061:1] info: generate keytag query _ta-4a5c-4f66. NULL IN
Mar  4 13:07:20 ipfire ntpd[14436]: Listen normally on 8 red0 71.233.118.65:123
Mar  4 13:07:20 ipfire ntpd[14436]: new interface(s) found: waking up resolver
Mar  4 13:07:25 ipfire ipsec: Creating route to 192.168.9.0/255.255.255.0 (via 192.168.20.1 and red0)
Mar  4 13:07:25 ipfire ipsec: Creating route to 192.168.101.0/255.255.255.0 (via 192.168.20.1 and red0)
Mar  4 13:07:27 ipfire ipsec_starter[2134]: Starting strongSwan 5.8.1 IPsec [starter]...
Mar  4 13:07:27 ipfire openvpnserver[2182]: OpenVPN 2.4.8 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on Dec 14 2019
Mar  4 13:07:27 ipfire openvpnserver[2182]: library versions: OpenSSL 1.1.1d  10 Sep 2019, LZO 2.09
Mar  4 13:07:27 ipfire openvpnserver[2183]: WARNING: --keepalive option is missing from server config
Mar  4 13:07:27 ipfire openvpnserver[2183]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Mar  4 13:07:27 ipfire openvpnserver[2183]: Diffie-Hellman initialized with 2048 bit key
Mar  4 13:07:27 ipfire openvpnserver[2183]: Failed to extract curve from certificate (UNDEF), using secp384r1 instead.
Mar  4 13:07:27 ipfire openvpnserver[2183]: ECDH curve secp384r1 added
Mar  4 13:07:27 ipfire openvpnserver[2183]: WARNING: normally if you use --mssfix and/or --fragment, you should also set --tun-mtu 1500 (currently it is 1400)
Mar  4 13:07:27 ipfire openvpnserver[2183]: ROUTE_GATEWAY 71.233.112.1/255.255.248.0 IFACE=red0 HWADDR=d0:67:e5:19:be:83
Mar  4 13:07:27 ipfire openvpnserver[2183]: TUN/TAP device tun0 opened
Mar  4 13:07:27 ipfire openvpnserver[2183]: TUN/TAP TX queue length set to 100
Mar  4 13:07:27 ipfire openvpnserver[2183]: /sbin/ip link set dev tun0 up mtu 1400
Mar  4 13:07:27 ipfire openvpnserver[2183]: /sbin/ip addr add dev tun0 local 10.115.104.1 peer 10.115.104.2
Mar  4 13:07:27 ipfire openvpnserver[2183]: /sbin/ip route add 10.115.104.0/24 via 10.115.104.2
Mar  4 13:07:27 ipfire openvpnserver[2183]: Could not determine IPv4/IPv6 protocol. Using AF_INET
Mar  4 13:07:27 ipfire openvpnserver[2183]: Socket Buffers: R=[212992->212992] S=[212992->212992]
Mar  4 13:07:27 ipfire openvpnserver[2183]: UDPv4 link local (bound): [AF_INET][undef]:1194
Mar  4 13:07:27 ipfire openvpnserver[2183]: UDPv4 link remote: [AF_UNSPEC]
Mar  4 13:07:27 ipfire openvpnserver[2183]: GID set to nobody
Mar  4 13:07:27 ipfire openvpnserver[2183]: UID set to nobody
Mar  4 13:07:27 ipfire openvpnserver[2183]: MULTI: multi_init called, r=256 v=256
Mar  4 13:07:27 ipfire openvpnserver[2183]: IFCONFIG POOL: base=10.115.104.4 size=62, ipv6=0
Mar  4 13:07:27 ipfire openvpnserver[2183]: ifconfig_pool_read(), in='es5rv,10.115.104.4', TODO: IPv6
Mar  4 13:07:27 ipfire openvpnserver[2183]: succeeded -> ifconfig_pool_set()
Mar  4 13:07:27 ipfire openvpnserver[2183]: IFCONFIG POOL LIST
Mar  4 13:07:27 ipfire openvpnserver[2183]: es5rv,10.115.104.4
Mar  4 13:07:27 ipfire openvpnserver[2183]: Initialization Sequence Completed
Mar  4 13:07:27 ipfire codel: Codel AQM has been enabled on 'tun0'.
Mar  4 13:07:29 ipfire ntpd[14436]: Listen normally on 9 tun0 10.115.104.1:123
Mar  4 13:07:29 ipfire ntpd[14436]: new interface(s) found: waking up resolver
14

Hi Eric,

I can see one thing that IMHO is not normal in your case.
The server can set the TTL of the DHCP-lease, and one hour is a normal choice for ISP’s. After this time, the DHCP-lease should be renewed, but only after 2xTTL the connection is really dropped if the lease is not renewed by then, so the client has ample time to renew it’s lease.
In your log ipfire acquires the lease at 12:01. At 12.58 (roughly one hour later) there is an entry “failed to renew DHCP, rebinding”. At 13:07 (i.e. 9 minutes later) is says “DHCP lease expired” and the connection is being taken down. I think that is not normal, that should happen only one hour (more or less) after the lease expired, that would be around 14:00. Your ISP gives the client a very small (only a few minutes) and non-standard time window to renew the DHCP-lease.
You might want to investigate with your ISP along these lines. In my case, my ISP suggested I do a wireshark trace, but that is quite a bit of work to analyse and I got away without doing that.
If you happen to have any standard router around you might try to connect that to the ISP and see if the router does the same thing - that could be a relatively quick and simple test.

I hope this will be helpful somewhat.

Best regards

Christoph

15

Dhcp report brocken answers from the server.
This was reported many times after an update from 7.2.3 to 8.xx and we are back to 7.2.3
This is really strange that you have it now also with dhcpcd 7.2.3

https://git.ipfire.org/?p=ipfire-2.x.git;a=history;f=lfs/dhcpcd;h=83252e8976d153b033923ffd757687f1598206e5;hb=e53c38aea14132da0fff15655735f673aab33c4a

Is this really a dhcpcd problem or it is something else. (server, modem, connection loss, suricata ???)

16

BFH… I need this fixed so I’ll start working on it. what is the best dev env for IPFire? I have the options of hyperV on win 10 and kvm on ubuntu.

shall we start a separate thread or is there a developers list I should join?

17

I tried ipfire on Hyper-V but could not get it working. As generation 2 it stops pretty much right away during the first step of the installation process. As generation 1 you can finish the installation, but it stalls during the startup afterwards. As far as I can tell thus, ipfire does not work on Hyper-V. I have no experience with KVM, you would have to try that yourself.
If you have a spare PC somewhere, you can just add a second network adapter and install ipfire on a standard PC. This might actually be the better option.

18

have provisional fix.

Looks like the problem is related to UDP checksum offloaded to the ethernet chip. see solutions in https://github.com/projectcalico/felix/issues/40

I used the ethtool -K rx off solution. there is also a firewall chain solution which I have not tried. not how to ensure this solution runs on boot.

19

Which nic you are using?

Strange thing is also that normally the kernel should not get packets with wrong checksums if the rx checksumming is enabled in hardware but the dhcp client log bad packages.

20

the changes only delayed the failure and added other errors like

Mar 10 01:43:10 ipfire dhcpcd[22910]: red0: invalid UDP packet from 54.239.221.120: No buffer space available
Mar 10 07:11:47 ipfire dhcpcd[22910]: red0: failed to renew DHCP, rebinding
Mar 10 07:11:47 ipfire dhcpcd[22910]: red0: truncated packet (128) from 192.168.20.1

this dhcp problem is breaking vpns and any persistent ssh connections. I’ve turned off ipsec in case something in IPSec is breaking DHCPCD. I may wipe and reinstall tonight if I have the time.