I am running core 170 , virtually on proxmox and am having a strange issue.
Every two hours like clockwork the dhcp lease to my RED interface is renewd and this causes some applications to freeze.
The mikrotik unit on RED interface has nothing in its logs pointing to hardware or software issues.
Any ideas what can be causing this?
Unbound in system log shows that dhcpd has been stopped and restarted
Hi,
well, I guess this is because your IPFire machine gets DHCP leases with a TTL of 120 minutes? Or did I misunderstand you, and you were expecting different DHCP lease parameters?
Could be an unreliable DHCP server, or intermittent connectivity failures. Instead of focusing on Unbound (which seems to be merely a symptom than the root cause), could you provide us with the DHCP client logs of IPFire?
Thanks, and best regards,
Peter Müller
In system logs I only have dhcp server and dns unbound where would I find the client logs?
The issue is when the lease is renewed I have loss of connection and on the system home page red interface will show connected for x no of seconds etc the time it takes to reconnect is the problem as various programs will give errors.
[ps this page is not freindly with my mobile browser as I need to type blind after 2 lines.
IPFire diagnostics
Section: unbound
Date: September 20, 2022
12:54:58 unbound: [1574:0] info: generate keytag query _ta-4a5c-4f66. NULL IN
12:54:57 unbound: [1574:0] info: start of service (unbound 1.16.2).
12:54:57 unbound: [1574:0] notice: init module 1: iterator
12:54:57 unbound: [1574:0] notice: init module 0: validator
12:54:57 unbound: [1574:0] notice: Restart of unbound 1.16.2.
12:54:57 unbound: [1574:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
12:54:57 unbound: [1574:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
12:54:57 unbound: [1574:0] info: service stopped (unbound 1.16.2).
12:54:46 unbound: [1574:0] info: start of service (unbound 1.16.2).
12:54:46 unbound: [1574:0] notice: init module 1: iterator
12:54:46 unbound: [1574:0] notice: init module 0: validator
09:56:06 unbound: [1572:0] info: 1.000000 2.000000 2
09:56:06 unbound: [1572:0] info: 0.524288 1.000000 3
09:56:06 unbound: [1572:0] info: 0.262144 0.524288 9
09:56:06 unbound: [1572:0] info: 0.131072 0.262144 8
09:56:06 unbound: [1572:0] info: 0.065536 0.131072 5
09:56:06 unbound: [1572:0] info: 0.032768 0.065536 5
09:56:06 unbound: [1572:0] info: 0.016384 0.032768 36
09:56:06 unbound: [1572:0] info: 0.008192 0.016384 23
09:56:06 unbound: [1572:0] info: 0.004096 0.008192 12
09:56:06 unbound: [1572:0] info: 0.000000 0.000001 2
09:56:06 unbound: [1572:0] info: lower(secs) upper(secs) recursions
09:56:06 unbound: [1572:0] info: [25%]=0.0125551 median[50%]=0.0234382 [75%]=0.0753664
09:56:06 unbound: [1572:0] info: histogram of recursion processing times
09:56:06 unbound: [1572:0] info: average recursion processing time 0.121459 sec
09:56:06 unbound: [1572:0] info: server stats for thread 0: requestlist max 3 avg 0.371429 exceeded 0 jostled 0
09:56:06 unbound: [1572:0] info: server stats for thread 0: 141 queries, 36 answers from cache, 105 recursions, 0 prefetch, 0 rejected by ip ratelimiting
09:56:06 unbound: [1572:0] info: service stopped (unbound 1.16.2).
09:27:27 unbound: [1572:0] info: generate keytag query _ta-4a5c-4f66. NULL IN
09:27:27 unbound: [1572:0] info: start of service (unbound 1.16.2).
09:27:26 unbound: [1572:0] notice: init module 1: iterator
09:27:26 unbound: [1572:0] notice: init module 0: validator
09:27:26 unbound: [1572:0] notice: Restart of unbound 1.16.2.
09:27:26 unbound: [1572:0] info: 1.000000 2.000000 3
09:27:26 unbound: [1572:0] info: 0.524288 1.000000 15
09:27:26 unbound: [1572:0] info: 0.262144 0.524288 21
09:27:26 unbound: [1572:0] info: 0.131072 0.262144 42
09:27:26 unbound: [1572:0] info: 0.065536 0.131072 31
09:27:26 unbound: [1572:0] info: 0.032768 0.065536 27
09:27:26 unbound: [1572:0] info: 0.016384 0.032768 73
09:27:26 unbound: [1572:0] info: 0.008192 0.016384 57
09:27:26 unbound: [1572:0] info: 0.004096 0.008192 36
09:27:26 unbound: [1572:0] info: 0.002048 0.004096 4
09:27:26 unbound: [1572:0] info: 0.001024 0.002048 7
09:27:26 unbound: [1572:0] info: 0.000512 0.001024 6
09:27:26 unbound: [1572:0] info: 0.000000 0.000001 1
09:27:26 unbound: [1572:0] info: lower(secs) upper(secs) recursions
09:27:26 unbound: [1572:0] info: [25%]=0.0120365 median[50%]=0.0277181 [75%]=0.131852
09:27:26 unbound: [1572:0] info: histogram of recursion processing times
09:27:26 unbound: [1572:0] info: average recursion processing time 0.111992 sec
09:27:26 unbound: [1572:0] info: server stats for thread 0: requestlist max 9 avg 0.865229 exceeded 0 jostled 0
09:27:26 unbound: [1572:0] info: server stats for thread 0: 589 queries, 266 answers from cache, 323 recursions, 48 prefetch, 0 rejected by ip ratelimiting
09:27:26 unbound: [1572:0] info: service stopped (unbound 1.16.2).
09:27:20 unbound: [1572:0] error: SERVFAIL <ksn-cinfo-geo.kaspersky-labs.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
09:27:20 unbound: [1572:0] error: SERVFAIL <ksn-cinfo-geo.kaspersky-labs.com.lan. AAAA IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
09:27:20 unbound: [1572:0] error: SERVFAIL <ksn-cinfo-geo.kaspersky-labs.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
09:27:20 unbound: [1572:0] error: SERVFAIL <ksn-cinfo-geo.kaspersky-labs.com. AAAA IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
09:27:20 unbound: [1572:0] error: SERVFAIL <dc1.ksn.kaspersky-labs.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
09:27:20 unbound: [1572:0] error: SERVFAIL <ksn-ca-geo.kaspersky-labs.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
09:27:20 unbound: [1572:0] error: SERVFAIL <ds.kaspersky.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
09:27:20 unbound: [1572:0] error: SERVFAIL <dc1.ksn.kaspersky-labs.com.lan. AAAA IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
09:27:20 unbound: [1572:0] error: SERVFAIL <ksn-ca-geo.kaspersky-labs.com.lan. AAAA IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
09:27:20 unbound: [1572:0] error: SERVFAIL <ds.kaspersky.com.lan. AAAA IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
09:27:20 unbound: [1572:0] error: SERVFAIL <ds.kaspersky.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
09:27:20 unbound: [1572:0] error: SERVFAIL <ds.kaspersky.com. AAAA IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
09:27:20 unbound: [1572:0] error: SERVFAIL <dc1.ksn.kaspersky-labs.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
09:27:20 unbound: [1572:0] error: SERVFAIL <ksn-ca-geo.kaspersky-labs.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
09:27:20 unbound: [1572:0] error: SERVFAIL <ksn-ca-geo.kaspersky-labs.com. AAAA IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
09:27:20 unbound: [1572:0] error: SERVFAIL <dc1.ksn.kaspersky-labs.com. AAAA IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
07:27:21 unbound: [1572:0] info: generate keytag query _ta-4a5c-4f66. NULL IN
07:27:20 unbound: [1572:0] info: start of service (unbound 1.16.2).
07:27:20 unbound: [1572:0] notice: init module 1: iterator
07:27:20 unbound: [1572:0] notice: init module 0: validator
07:27:20 unbound: [1572:0] notice: Restart of unbound 1.16.2.
07:27:20 unbound: [1572:0] info: 2.000000 4.000000 1
07:27:20 unbound: [1572:0] info: 1.000000 2.000000 15
07:27:20 unbound: [1572:0] info: 0.524288 1.000000 20
07:27:20 unbound: [1572:0] info: 0.262144 0.524288 35
07:27:20 unbound: [1572:0] info: 0.131072 0.262144 70
07:27:20 unbound: [1572:0] info: 0.065536 0.131072 17
07:27:20 unbound: [1572:0] info: 0.032768 0.065536 47
07:27:20 unbound: [1572:0] info: 0.016384 0.032768 91
07:27:20 unbound: [1572:0] info: 0.008192 0.016384 69
07:27:20 unbound: [1572:0] info: 0.004096 0.008192 57
07:27:20 unbound: [1572:0] info: 0.000256 0.000512 1
07:27:20 unbound: [1572:0] info: 0.000000 0.000001 6
07:27:20 unbound: [1572:0] info: lower(secs) upper(secs) recursions
07:27:20 unbound: [1572:0] info: [25%]=0.0133268 median[50%]=0.0310576 [75%]=0.194267
07:27:20 unbound: [1572:0] info: histogram of recursion processing times
07:27:20 unbound: [1572:0] info: average recursion processing time 0.164537 sec
07:27:20 unbound: [1572:0] info: server stats for thread 0: requestlist max 6 avg 0.34642 exceeded 0 jostled 0
07:27:20 unbound: [1572:0] info: server stats for thread 0: 577 queries, 148 answers from cache, 429 recursions, 4 prefetch, 0 rejected by ip ratelimiting
07:27:20 unbound: [1572:0] info: service stopped (unbound 1.16.2).
05:27:16 unbound: [1572:0] info: generate keytag query _ta-4a5c-4f66. NULL IN
05:27:16 unbound: [1572:0] info: start of service (unbound 1.16.2).
05:27:16 unbound: [1572:0] notice: init module 1: iterator
05:27:16 unbound: [1572:0] notice: init module 0: validator
05:27:16 unbound: [1572:0] notice: Restart of unbound 1.16.2.
05:27:16 unbound: [1572:0] info: 1.000000 2.000000 3
05:27:16 unbound: [1572:0] info: 0.524288 1.000000 8
05:27:16 unbound: [1572:0] info: 0.262144 0.524288 21
05:27:16 unbound: [1572:0] info: 0.131072 0.262144 36
05:27:16 unbound: [1572:0] info: 0.065536 0.131072 19
05:27:16 unbound: [1572:0] info: 0.032768 0.065536 22
05:27:16 unbound: [1572:0] info: 0.016384 0.032768 49
05:27:16 unbound: [1572:0] info: 0.008192 0.016384 28
05:27:16 unbound: [1572:0] info: 0.004096 0.008192 23
05:27:16 unbound: [1572:0] info: 0.000000 0.000001 7
05:27:16 unbound: [1572:0] info: lower(secs) upper(secs) recursions
05:27:16 unbound: [1572:0] info: [25%]=0.0152137 median[50%]=0.0342575 [75%]=0.182044
05:27:16 unbound: [1572:0] info: histogram of recursion processing times
05:27:16 unbound: [1572:0] info: average recursion processing time 0.134063 sec
05:27:16 unbound: [1572:0] info: server stats for thread 0: requestlist max 3 avg 0.155963 exceeded 0 jostled 0
05:27:16 unbound: [1572:0] info: server stats for thread 0: 350 queries, 134 answers from cache, 216 recursions, 2 prefetch, 0 rejected by ip ratelimiting
05:27:16 unbound: [1572:0] info: service stopped (unbound 1.16.2).
03:27:06 unbound: [1572:0] info: generate keytag query _ta-4a5c-4f66. NULL IN
03:27:06 unbound: [1572:0] info: start of service (unbound 1.16.2).
03:27:06 unbound: [1572:0] notice: init module 1: iterator
03:27:06 unbound: [1572:0] notice: init module 0: validator
03:27:06 unbound: [1572:0] notice: Restart of unbound 1.16.2.
03:27:06 unbound: [1572:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
03:27:06 unbound: [1572:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
03:27:06 unbound: [1572:0] info: service stopped (unbound 1.16.2).
03:26:54 unbound: [1572:0] info: start of service (unbound 1.16.2).
03:26:54 unbound: [1572:0] notice: init module 1: iterator
03:26:54 unbound: [1572:0] notice: init module 0: validator
01:55:45 unbound: [1731:0] info: 1.000000 2.000000 4
01:55:45 unbound: [1731:0] info: 0.524288 1.000000 9
01:55:45 unbound: [1731:0] info: 0.262144 0.524288 15
01:55:45 unbound: [1731:0] info: 0.131072 0.262144 43
01:55:45 unbound: [1731:0] info: 0.065536 0.131072 23
01:55:45 unbound: [1731:0] info: 0.032768 0.065536 29
01:55:45 unbound: [1731:0] info: 0.016384 0.032768 59
01:55:45 unbound: [1731:0] info: 0.008192 0.016384 94
01:55:45 unbound: [1731:0] info: 0.004096 0.008192 40
01:55:45 unbound: [1731:0] info: 0.000000 0.000001 9
01:55:45 unbound: [1731:0] info: lower(secs) upper(secs) recursions
01:55:45 unbound: [1731:0] info: [25%]=0.0110026 median[50%]=0.0217991 [75%]=0.101866
01:55:45 unbound: [1731:0] info: histogram of recursion processing times
01:55:45 unbound: [1731:0] info: average recursion processing time 0.095562 sec
01:55:45 unbound: [1731:0] info: server stats for thread 0: requestlist max 6 avg 0.23565 exceeded 0 jostled 0
01:55:45 unbound: [1731:0] info: server stats for thread 0: 482 queries, 157 answers from cache, 325 recursions, 6 prefetch, 0 rejected by ip ratelimiting
01:55:45 unbound: [1731:0] info: service stopped (unbound 1.16.2).
00:05:28 unbound: [1731:0] info: generate keytag query _ta-4a5c-4f66. NULL IN
00:05:28 unbound: [1731:0] info: start of service (unbound 1.16.2).
00:05:28 unbound: [1731:0] notice: init module 1: iterator
00:05:28 unbound: [1731:0] notice: init module 0: validator
00:05:28 unbound: [1731:0] notice: Restart of unbound 1.16.2.
00:05:28 unbound: [1731:0] info: 0.524288 1.000000 1
00:05:28 unbound: [1731:0] info: 0.131072 0.262144 3
00:05:28 unbound: [1731:0] info: 0.016384 0.032768 1
00:05:28 unbound: [1731:0] info: 0.000512 0.001024 8
00:05:28 unbound: [1731:0] info: 0.000256 0.000512 12
00:05:28 unbound: [1731:0] info: 0.000128 0.000256 28
00:05:28 unbound: [1731:0] info: lower(secs) upper(secs) recursions
00:05:28 unbound: [1731:0] info: [25%]=0.000188571 median[50%]=0.000249143 [75%]=0.000506667
00:05:28 unbound: [1731:0] info: histogram of recursion processing times
00:05:28 unbound: [1731:0] info: average recursion processing time 0.022884 sec
00:05:28 unbound: [1731:0] info: server stats for thread 0: requestlist max 7 avg 0.724138 exceeded 0 jostled 0
00:05:28 unbound: [1731:0] info: server stats for thread 0: 236 queries, 183 answers from cache, 53 recursions, 5 prefetch, 0 rejected by ip ratelimiting
00:05:28 unbound: [1731:0] info: service stopped (unbound 1.16.2).
00:05:26 unbound: [1731:0] info: generate keytag query _ta-4a5c-4f66. NULL IN
00:05:25 unbound: [1731:0] error: SERVFAIL <scontent-jnb1-1.xx.fbcdn.net. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:24 unbound: [1731:0] error: SERVFAIL <connectivitycheck.gstatic.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:24 unbound: [1731:0] error: SERVFAIL <connectivitycheck.gstatic.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:23 unbound: [1731:0] error: SERVFAIL <imap.gmail.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:23 unbound: [1731:0] error: SERVFAIL <imap.gmail.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:22 unbound: [1731:0] error: SERVFAIL <alt1-mtalk.google.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:22 unbound: [1731:0] error: SERVFAIL <alt1-mtalk.google.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:22 unbound: [1731:0] error: SERVFAIL <servicesupport.hicloud.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:22 unbound: [1731:0] error: SERVFAIL <mtalk.google.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:22 unbound: [1731:0] error: SERVFAIL <edge-mqtt.facebook.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:22 unbound: [1731:0] error: SERVFAIL <mtalk.google.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:21 unbound: [1731:0] error: SERVFAIL <google.com. MX IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:21 unbound: [1731:0] error: SERVFAIL <www.google.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:21 unbound: [1731:0] error: SERVFAIL <www.google.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:21 unbound: [1731:0] error: SERVFAIL <www.baidu.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:21 unbound: [1731:0] error: SERVFAIL <www.baidu.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:21 unbound: [1731:0] error: SERVFAIL <googleads.g.doubleclick.net.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:21 unbound: [1731:0] error: SERVFAIL <googleads.g.doubleclick.net. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:20 unbound: [1731:0] error: SERVFAIL <graph.facebook.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:20 unbound: [1731:0] error: SERVFAIL <graph.facebook.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:20 unbound: [1731:0] error: SERVFAIL <android.googleapis.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:20 unbound: [1731:0] error: SERVFAIL <android.googleapis.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:20 unbound: [1731:0] error: SERVFAIL <people-pa.googleapis.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:20 unbound: [1731:0] error: SERVFAIL <footprints-pa.googleapis.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:20 unbound: [1731:0] error: SERVFAIL <people-pa.googleapis.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:20 unbound: [1731:0] error: SERVFAIL <footprints-pa.googleapis.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:20 unbound: [1731:0] error: SERVFAIL <dc.dqa.samsung.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:19 unbound: [1731:0] error: SERVFAIL <BCMLS2.glpals.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:19 unbound: [1731:0] error: SERVFAIL <app-measurement.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:19 unbound: [1731:0] error: SERVFAIL <app-measurement.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:19 unbound: [1731:0] error: SERVFAIL <pop3.bacchus.co.za.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:19 unbound: [1731:0] error: SERVFAIL <pop3.bacchus.co.za. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:18 unbound: [1731:0] error: SERVFAIL <connectivitycheck.gstatic.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:18 unbound: [1731:0] error: SERVFAIL <static.whatsapp.net.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:18 unbound: [1731:0] error: SERVFAIL <static.whatsapp.net. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:18 unbound: [1731:0] error: SERVFAIL <g.whatsapp.net.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:18 unbound: [1731:0] error: SERVFAIL <g.whatsapp.net. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:18 unbound: [1731:0] error: SERVFAIL <clients3.google.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:18 unbound: [1731:0] error: SERVFAIL <clients3.google.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:18 unbound: [1731:0] error: SERVFAIL <scontent-jnb1-1.xx.fbcdn.net. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:18 unbound: [1731:0] error: SERVFAIL <edge-mqtt.facebook.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:18 unbound: [1731:0] error: SERVFAIL <www.googleapis.com.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:18 unbound: [1731:0] error: SERVFAIL <www.googleapis.com. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:18 unbound: [1731:0] error: SERVFAIL <2.android.pool.ntp.org.lan. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:18 unbound: [1731:0] error: SERVFAIL <2.android.pool.ntp.org. A IN>: all the configured stub or forward servers failed, at zone . upstream server timeout
00:05:16 unbound: [1731:0] info: start of service (unbound 1.16.2).
00:05:16 unbound: [1731:0] notice: init module 1: iterator
00:05:16 unbound: [1731:0] notice: init module 0: validator
00:04:18 unbound: [1591:0] info: 2.000000 4.000000 1
00:04:18 unbound: [1591:0] info: 1.000000 2.000000 8
00:04:18 unbound: [1591:0] info: 0.524288 1.000000 17
00:04:18 unbound: [1591:0] info: 0.262144 0.524288 14
00:04:18 unbound: [1591:0] info: 0.131072 0.262144 75
00:04:18 unbound: [1591:0] info: 0.065536 0.131072 21
00:04:18 unbound: [1591:0] info: 0.032768 0.065536 45
00:04:18 unbound: [1591:0] info: 0.016384 0.032768 85
00:04:18 unbound: [1591:0] info: 0.008192 0.016384 84
00:04:18 unbound: [1591:0] info: 0.004096 0.008192 77
00:04:18 unbound: [1591:0] info: 0.001024 0.002048 1
00:04:18 unbound: [1591:0] info: 0.000000 0.000001 19
00:04:18 unbound: [1591:0] info: lower(secs) upper(secs) recursions
00:04:18 unbound: [1591:0] info: [25%]=0.00963048 median[50%]=0.024576 [75%]=0.136752
00:04:18 unbound: [1591:0] info: histogram of recursion processing times
00:04:18 unbound: [1591:0] info: average recursion processing time 0.113884 sec
00:04:18 unbound: [1591:0] info: server stats for thread 0: requestlist max 15 avg 0.88172 exceeded 0 jostled 0
00:04:18 unbound: [1591:0] info: server stats for thread 0: 711 queries, 264 answers from cache, 447 recursions, 18 prefetch, 0 rejected by ip ratelimiting
00:04:18 unbound: [1591:0] info: service stopped (unbound 1.16.2).
IPFire for its RED interface is the dhcp client for your ISP’s dhcp server.
You can find those logs from the WUI menu Logs - System Logs and select RED in the dropdown menu and then press Update.
If you look, using the console, in the
/var/ipfire/dhcpc/dhcpcd-red0.info
file there is a line there that says what dhcp lease time your ISP has assigned. Mine has the entry 3600 which is in minutes so equates to 60 hours or 2.5 days.
Normally when a lease is renewed by dhcp it is done before the whole lease time has been expired so the connection stays in place and the server and client just agree to continue the lease.
If your system is losing the lease and it has to be completely renewed and you have no connection while that happening, that is not normal.
I would expect to see some messages in the RED System Log related to that occurring.
That is exactly the issue I am having
| :55:06 | dhcpcd[1705] | : red0: adding route to 192.168.5.0/24 |
|---|---|---|
| 14:55:06 | dhcpcd[1705] | : red0: leased 192.168.5.116 for 172800 seconds |
| 14:55:00 | dhcpcd[1705] | : red0: probing address 192.168.5.116/24 |
| 14:55:00 | dhcpcd[1705] | : red0: offered 192.168.5.116 from 192.168.5.1 |
| 14:55:00 | dhcpcd[1705] | : red0: soliciting a DHCP lease |
| 14:54:55 | dhcpcd[1705] | : red0: deleting default route via 192.168.5.1 |
| 14:54:55 | dhcpcd[1705] | : red0: deleting route to 192.168.5.0/24 |
| 14:54:55 | dhcpcd[1705] | : red0: DHCP lease expired |
| 14:39:55 | dhcpcd[1705] | : red0: failed to renew DHCP, rebinding |
| 12:54:54 | dhcpcd[1705] | : red0: adding default route via 192.168.5.1 |
| 12:54:54 | dhcpcd[1705] | : red0: adding route to 192.168.5.0/24 |
| 12:54:54 | dhcpcd[1705] | : red0: leased 192.168.5.116 for 7200 seconds |
| 12:54:49 | dhcpcd[1705] | : red0: probing address 192.168.5.116/24 |
| 12:54:49 | dhcpcd[1705] | : red0: offered 192.168.5.116 from 192.168.5.1 |
| 12:54:49 | dhcpcd[1705] | : red0: soliciting a DHCP lease |
| 12:54:48 | dhcpcd[1705] | : red0: soliciting an IPv6 router |
| 12:54:48 | dhcpcd[1705] | : ipv6_addaddr1: Permission denied |
| 12:54:48 | dhcpcd[1705] | : red0: adding address fe80::1451:f5ff:fed1:8f71 |
| 12:54:48 | dhcpcd[1705] | : red0: IAID f5:d1:8f:71 |
| 12:54:48 | dhcpcd[1705] | : DUID 00:04:38:36:b7:ca:99:ea:42:a0:96:d9:6f:ee:7c:bc:3c:7e |
| 12:54:48 | dhcpcd[1702] | : dhcpcd-9.4.1 starting |
| 09:56:05 | dhcpcd[1703] | : red0: deleting default route via 192.168.5.1 |
| 09:56:05 | dhcpcd[1703] | : red0: deleting route to 192.168.5.0/24 |
| 09:56:05 | dhcpcd[1703] | : red0: releasing lease of 192.168.5.116 |
| 09:56:05 | dhcpcd[1703] | : red0: removing interface |
| 09:56:05 | dhcpcd[1703] | : received SIGALRM, releasing |
| 09:56:05 | dhcpcd[25535] | : waiting for pid 1702 to exit |
| 09:56:05 | dhcpcd[25535] | : sending signal ALRM to pid 1702 |
| 09:27:23 | dhcpcd[1703] | : red0: adding default route via 192.168.5.1 |
| 09:27:23 | dhcpcd[1703] | : red0: adding route to 192.168.5.0/24 |
| 09:27:23 | dhcpcd[1703] | : red0: leased 192.168.5.116 for 7200 seconds |
| 09:27:18 | dhcpcd[1703] | : red0: probing address 192.168.5.116/24 |
| 09:27:17 | dhcpcd[1703] | : red0: offered 192.168.5.116 from 192.168.5.1 |
| 09:27:17 | dhcpcd[1703] | : red0: soliciting a DHCP lease |
| 09:27:17 | dhcpcd[1703] | : red0: deleting default route via 192.168.5.1 |
| 09:27:17 | dhcpcd[1703] | : red0: deleting route to 192.168.5.0/24 |
| 09:27:17 | dhcpcd[1703] | : red0: DHCP lease expired |
| 09:12:17 | dhcpcd[1703] | : red0: failed to renew DHCP, rebinding |
| 07:27:17 | dhcpcd[1703] | : red0: adding default route via 192.168.5.1 |
| 07:27:17 | dhcpcd[1703] | : red0: adding route to 192.168.5.0/24 |
| 07:27:17 | dhcpcd[1703] | : red0: leased 192.168.5.116 for 7200 seconds |
| 07:27:12 | dhcpcd[1703] | : red0: probing address 192.168.5.116/24 |
| 07:27:11 | dhcpcd[1703] | : red0: offered 192.168.5.116 from 192.168.5.1 |
| 07:27:11 | dhcpcd[1703] | : red0: soliciting a DHCP lease |
| 07:27:10 | dhcpcd[1703] | : red0: deleting default route via 192.168.5.1 |
| 07:27:10 | dhcpcd[1703] | : red0: deleting route to 192.168.5.0/24 |
| 07:27:10 | dhcpcd[1703] | : red0: DHCP lease expired |
| 07:12:10 | dhcpcd[1703] | : red0: failed to renew DHCP, rebinding |
| 05:27:10 | dhcpcd[1703] | : red0: adding default route via 192.168.5.1 |
| 05:27:10 | dhcpcd[1703] | : red0: adding route to 192.168.5.0/24 |
| 05:27:10 | dhcpcd[1703] | : red0: leased 192.168.5.116 for 7200 seconds |
| 05:27:05 | dhcpcd[1703] | : red0: probing address 192.168.5.116/24 |
| 05:27:05 | dhcpcd[1703] | : red0: offered 192.168.5.116 from 192.168.5.1 |
| 05:27:05 | dhcpcd[1703] | : red0: soliciting a DHCP lease |
| 05:27:04 | dhcpcd[1703] | : red0: deleting default route via 192.168.5.1 |
| 05:27:04 | dhcpcd[1703] | : red0: deleting route to 192.168.5.0/24 |
| 05:27:04 | dhcpcd[1703] | : red0: DHCP lease expired |
| 05:12:04 | dhcpcd[1703] | : red0: failed to renew DHCP, rebinding |
| 03:27:03 | dhcpcd[1703] | : red0: adding default route via 192.168.5.1 |
| 03:27:03 | dhcpcd[1703] | : red0: adding route to 192.168.5.0/24 |
| 03:27:03 | dhcpcd[1703] | : red0: leased 192.168.5.116 for 7200 seconds |
| 03:26:58 | dhcpcd[1703] | : red0: probing address 192.168.5.116/24 |
| 03:26:57 | dhcpcd[1703] | : red0: offered 192.168.5.116 from 192.168.5.1 |
| 03:26:57 | dhcpcd[1703] | : red0: soliciting a DHCP lease |
| 03:26:57 | dhcpcd[1703] | : red0: soliciting an IPv6 router |
| 03:26:56 | dhcpcd[1703] | : ipv6_addaddr1: Permission denied |
| 03:26:56 | dhcpcd[1703] | : red0: adding address fe80::1451:f5ff:fed1:8f71 |
| 03:26:56 | dhcpcd[1703] | : red0: IAID f5:d1:8f:71 |
| 03:26:56 | dhcpcd[1703] | : DUID 00:04:38:36:b7:ca:99:ea:42:a0:96:d9:6f:ee:7c:bc:3c:7e |
| 03:26:56 | dhcpcd[1700] | : dhcpcd-9.4.1 starting |
| 01:55:44 | dhcpcd[1862] | : red0: deleting default route via 192.168.5.1 |
| 01:55:44 | dhcpcd[1862] | : red0: deleting route to 192.168.5.0/24 |
| 01:55:44 | dhcpcd[1862] | : red0: removing interface |
| 01:55:44 | dhcpcd[1862] | : received SIGALRM, releasing |
| 01:55:44 | dhcpcd[8832] | : waiting for pid 1861 to exit |
| 01:55:44 | dhcpcd[8832] | : sending signal ALRM to pid 1861 |
| 01:50:25 | dhcpcd[1862] | : red0: failed to renew DHCP, rebinding |
| 00:05:25 | dhcpcd[1862] | : red0: adding default route via 192.168.5.1 |
| 00:05:25 | dhcpcd[1862] | : red0: adding route to 192.168.5.0/24 |
| 00:05:25 | dhcpcd[1862] | : red0: leased 192.168.5.116 for 7200 seconds |
| 00:05:20 | dhcpcd[1862] | : red0: probing address 192.168.5.116/24 |
| 00:05:20 | dhcpcd[1862] | : red0: offered 192.168.5.116 from 192.168.5.1 |
| 00:05:20 | dhcpcd[1862] | : red0: soliciting a DHCP lease |
| 00:05:18 | dhcpcd[1862] | : red0: soliciting an IPv6 router |
| 00:05:18 | dhcpcd[1862] | : ipv6_addaddr1: Permission denied |
| 00:05:18 | dhcpcd[1862] | : red0: adding address fe80::1451:f5ff:fed1:8f71 |
| 00:05:18 | dhcpcd[1862] | : red0: IAID f5:d1:8f:71 |
| 00:05:17 | dhcpcd[1862] | : DUID 00:04:38:36:b7:ca:99:ea:42:a0:96:d9:6f:ee:7c:bc:3c:7e |
| 00:05:17 | dhcpcd[1859] | : dhcpcd-9.4.1 starting |
| 00:04:17 | dhcpcd[1722] | : red0: deleting default route via 192.168.5.1 |
| 00:04:17 | dhcpcd[1722] | : red0: deleting route to 192.168.5.0/24 |
| 00:04:17 | dhcpcd[1722] | : red0: removing interface |
| 00:04:17 | dhcpcd[1722] | : received SIGALRM, releasing |
| 00:04:17 | dhcpcd[20669] | : waiting for pid 1721 to exit |
| 00:04:17 | dhcpcd[20669] | : sending signal ALRM to pid 1721 |
| 00:03:35 | dhcpcd[1722] | : red0: failed to renew DHCP, rebinding |
I am replying to this on my Android phone and the window scrolls up as i type so there is no problem seeing what is being typed.
I would look at how the mobile browser is setup. It should always be able to show you the lines you are typing.
So these lines are indicating that your ISP is providing a 2 hour lease.
What should happen is that before the two hours are up the lease should be renewed, which would occur without any interruption to the traffic.
You have the message
followed by
So your ISP’s dhcp server is failing to renew the dhcp lease for some reason and then the lease time is expiring and you lose the connection while a complete new dhcp offering is made and accepted. The thing is the new dhcp offer is for exactly the same IP address as previously so I don’t understand why your ISP’s dhcp server could not renew it.
I think you need to raise this with your ISP. Their dhcp server should be renewing the lease. They should at least be able to tell you why their dhcp server failed to renew the dhcp lease and had to rebind.
Just to check and be sure, it would be good to confirm the contents of your
/var/ipfire/dhcpc/dhcpcd.conf file.
This is created automatically but it would be good to confirm that it has not become corrupted somehow.
I have just noticed this line in your original post.
Is the mikrotik unit from your ISP? Is it set up to give out dhcp leases to your virtual IPFire on proxmox.
If that is the case then I would look at the dhcp server logs on the mikrotik to see what info is there for why it did not renew the lease to IPFire.
Hi Adolf,
Thanks for the reply. First off if my ipfire vm is shutdown and I configure dhcp on my mikrotik I have no connection / lease renewal issues.
I am paying for a connection via a freind that runs over a transparent ptp bridge using two mikrotik units and on the other end it is connected to his tplink.(technically the same as a lan cable)
It is only when ipfire handles dhcp that I have this problem, if I configure the mikrotik on my end as the dhcp server and ipfire as the dns it works.
The aim of my setup is to use the proxy and url filter (also issues there but need a stable connection first).
I was thinking to install a fresh vm to test but here in South Affica we have rolling blackouts 3 times a day
(forcing me to shutdown my server each time as I cannot afford a power solution for all the equipment)
I currently have 4 - 6 hours of power at a time and if they have no issues when switching on.
It is an odd situation with the dhcp client. I have checked on his tplink and it is set to 120 min. It is only ipfire suffering from it.
Switched to via browser and much better. Firefox and xbrowser both have issues with the site
dhcpd.conf is there and looks standard as I have not had any need to make changes there.
