Udhcp renewal + adblock - is this log normal?

Recently (< 30 days) my logs began filling with near hourly WAN address renewals and the resulting triggered firewall/unbound/adblock activity. It might be that Comcast has shortened their renewal times for me within the past few weeks. I have a couple questions:

  • The lease times are usually 3600 or 7200 units. If those are seconds, why does the following renewal request happen after only 30m or 60m respectively (i.e. 1/2 the lease time)?
  • Given that the assigned WAN address doesn't change, is it normal for the 'ifupdate' activity to trigger for the firewall, unbound, and adblock? Yes adblock is configured with the Startup Trigger Interface set to WAN.
  • Any advice for how best to calm my logs? If the above behavior is all normal I'm thinking of configuring adblock to use a restart time instead of interface trigger.

Thanks for any input.

[ OpenWrt 21.02.1 on TP-Link Archer A7 ]

$ egrep 'udhcp|firewall|instance' [ addresses redacted but unchanging ]

Sun Jan  2 11:27:59 2022 daemon.notice netifd: wan (2323): udhcpc: sending renew to XX.XX.XX.XX
Sun Jan  2 11:27:59 2022 daemon.notice netifd: wan (2323): udhcpc: lease of YY.YY.YY.YY obtained, lease time 7200
Sun Jan  2 11:28:01 2022 user.notice firewall: Reloading firewall due to ifupdate of wan (eth0.2)
Sun Jan  2 11:28:05 2022 user.info adblock-4.1.3[5689]: adblock instance started ::: action: start, priority: 0, pid: 5689
Sun Jan  2 12:27:59 2022 daemon.notice netifd: wan (2323): udhcpc: sending renew to XX.XX.XX.XX
Sun Jan  2 12:27:59 2022 daemon.notice netifd: wan (2323): udhcpc: lease of YY.YY.YY.YY obtained, lease time 3600
Sun Jan  2 12:27:59 2022 user.notice firewall: Reloading firewall due to ifupdate of wan (eth0.2)
Sun Jan  2 12:28:05 2022 user.info adblock-4.1.3[7222]: adblock instance started ::: action: start, priority: 0, pid: 7222
Sun Jan  2 12:57:59 2022 daemon.notice netifd: wan (2323): udhcpc: sending renew to XX.XX.XX.XX
Sun Jan  2 12:57:59 2022 daemon.notice netifd: wan (2323): udhcpc: lease of YY.YY.YY.YY obtained, lease time 7200
Sun Jan  2 12:57:59 2022 user.notice firewall: Reloading firewall due to ifupdate of wan (eth0.2)
Sun Jan  2 12:58:05 2022 user.info adblock-4.1.3[8221]: adblock instance started ::: action: start, priority: 0, pid: 8221
Sun Jan  2 13:57:59 2022 daemon.notice netifd: wan (2323): udhcpc: sending renew to XX.XX.XX.XX
Sun Jan  2 13:57:59 2022 daemon.notice netifd: wan (2323): udhcpc: lease of YY.YY.YY.YY obtained, lease time 3600
Sun Jan  2 13:58:00 2022 user.notice firewall: Reloading firewall due to ifupdate of wan (eth0.2)
Sun Jan  2 13:58:05 2022 user.info adblock-4.1.3[9270]: adblock instance started ::: action: start, priority: 0, pid: 9270
Sun Jan  2 14:27:59 2022 daemon.notice netifd: wan (2323): udhcpc: sending renew to XX.XX.XX.XX
Sun Jan  2 14:27:59 2022 daemon.notice netifd: wan (2323): udhcpc: lease of YY.YY.YY.YY obtained, lease time 7200
Sun Jan  2 14:28:00 2022 user.notice firewall: Reloading firewall due to ifupdate of wan (eth0.2)
Sun Jan  2 14:28:05 2022 user.info adblock-4.1.3[10287]: adblock instance started ::: action: start, priority: 0, pid: 10287
1 Like

It is convention that DHCP clients request a renewal of the DHCP lease after half of the lease time provided by your ISP. The intervals given by your ISP are authoritative, you can't really avoid or change those (my own ISP sets an hour as lease time as well, which also results in half-hour renewals (and a number of other oddities with their IPv6 implementation, but that's orthogonal to your situation)). What you're seeing is normal and expected behaviour.

1 Like

Some heads up: If you change to time based adblock reverts this in my case once in a while when I choose to restart adblock to update the blocklists which I usally load as a backup from an USB stick. Perhaps not happening if you setup a chron refresh timer as offered.

A belated thanks for confirming the lease time renewal behavior!

Thanks. I'm not exactly sure what you meant by "adblock reverts this", but I did change to using a refresh timer via Luci (added a cron job to reload). And it has been working over the past few days -- my logs no longer cluttered by hourly DHCP updates.

Can you explain what this means...or what you configured previously?

Someone in the community is having a similar issue; and they have Adblock installed.

Thanks.

See:

What I did was:

  • Go to luci->Services->Adblock
  • Under Information (on the default Overview tab) click the button "Refresh Timer"
  • Fill out the form to create a cron job. For "Adblock action" choose Reload. Pick whatever week days / time you prefer. Press Save.
  • Afterwards you can press the "Refresh Timer" button again and it will show your cron job under "Existing jobs". Mine looks like:
    1> 32 04 * * 1,4 /etc/init.d/adblock reload
    (i.e. 2 days a week early in the morning, adblock gets reloaded)
  • Then back on luci->Services->Adblock->Overview under Settings->General Settings->Startup Trigger Interface, the help hint says " Choose 'unspecified' to use a classic startup timeout instead of a network trigger." I did that multiple times, but it still shows "wan" when I look at it again. And 'uci show adblock' has:
    adblock.global.adb_trigger='wan'

But it worked to squelch the log spam. My system log has no spam about udhcp renewal, firewall reloading, unbound, or adblock relating to my ISP's dhcp renewal. I do get adblock and unbound logging for the adblock reload cron job.

[edit: although I've marked this as the "solution" because it works around the problem, I think this is actually a bug in the default adblock trigger. When dhcp is renewed and the WAN address doesn't change, it would be preferable if adblock didn't trigger a reload. IMHO.]

2 Likes

Sorry for the confusion, when I wrote 'time based' I meant setting the startup trigger to 'unspecified'. This will be reverted by adblock as you already encountered yourself.

I mark the config line with # then it is shown as 'unspecified' in luci

Thanks, I finally understood what you meant earlier about reverting. For my purpose at least, apparently it isn't necessary to truly "unspecify" the startup trigger so long as the Refresh Timer cron job has been created. Apparently that decouples the task of starting up from the task of reloading the adblock database. And apparently that stops adblock from seeing WAN dhcp renewals as triggers.

I say apparently because in checking my recent logs, although the adblock restart "spam" is gone, my ISP has returned to longer and unvarying dhcp lease times:
$ logread | egrep 'udhcp|firewall|instance'

Thu Jan 20 04:32:00 2022 user.info adblock-4.1.3[9592]: adblock instance started ::: action: reload, priority: 0, pid: 9592
Thu Jan 20 18:16:03 2022 daemon.notice netifd: wan (2257): udhcpc: sending renew to XX.XX.XX.XX
Thu Jan 20 18:16:03 2022 daemon.notice netifd: wan (2257): udhcpc: lease of YY.YY.YY.YY obtained, lease time 345600
Sat Jan 22 18:16:03 2022 daemon.notice netifd: wan (2257): udhcpc: sending renew to XX.XX.XX.XX
Sat Jan 22 18:16:03 2022 daemon.notice netifd: wan (2257): udhcpc: lease of YY.YY.YY.YY obtained, lease time 345600
Mon Jan 24 04:32:01 2022 user.info adblock-4.1.3[29060]: adblock instance started ::: action: reload, priority: 0, pid: 29060
Mon Jan 24 18:16:02 2022 daemon.notice netifd: wan (2257): udhcpc: sending renew to XX.XX.XX.XX
Mon Jan 24 18:16:02 2022 daemon.notice netifd: wan (2257): udhcpc: lease of YY.YY.YY.YY obtained, lease time 345600
Wed Jan 26 18:16:02 2022 daemon.notice netifd: wan (2257): udhcpc: sending renew to XX.XX.XX.XX
Wed Jan 26 18:16:02 2022 daemon.notice netifd: wan (2257): udhcpc: lease of YY.YY.YY.YY obtained, lease time 345600
Thu Jan 27 04:32:00 2022 user.info adblock-4.1.3[4334]: adblock instance started ::: action: reload, priority: 0, pid: 4334
Fri Jan 28 18:16:03 2022 daemon.notice netifd: wan (2257): udhcpc: sending renew to XX.XX.XX.XX
Fri Jan 28 18:16:03 2022 daemon.notice netifd: wan (2257): udhcpc: lease of YY.YY.YY.YY obtained, lease time 345600
Sun Jan 30 18:16:03 2022 daemon.notice netifd: wan (2257): udhcpc: sending renew to XX.XX.XX.XX
Sun Jan 30 18:16:03 2022 daemon.notice netifd: wan (2257): udhcpc: lease of YY.YY.YY.YY obtained, lease time 345600
Mon Jan 31 04:32:01 2022 user.info adblock-4.1.3[11095]: adblock instance started ::: action: reload, priority: 0, pid: 11095
Tue Feb  1 18:16:02 2022 daemon.notice netifd: wan (2257): udhcpc: sending renew to XX.XX.XX.XX
Tue Feb  1 18:16:02 2022 daemon.notice netifd: wan (2257): udhcpc: lease of YY.YY.YY.YY obtained, lease time 345600

What's missing from the current logs is the varying lease time. In the original log you can see lease time ping pong between 3600 and 7200. I can no longer test if that difference was causing the 'ifupdate' events as posed by dave14305 in a post in the topic Firewall reloading every half an hour after udhcpc: sending renew.

This topic was automatically closed 10 days after the last reply. New replies are no longer allowed.