Please explain these log messages
-
Hello all,
I have several 2.4GHz WiFi devices that disconnect randomly, and all at the same time. It's only for a few seconds but long enough to be picked up by Home Assistant and cause me issues.
The devices are allocated an IP via mapping in DHCP so they always have the same IP. The lease time is 7200 seconds so they should get renewed every hour.
When a disconnection happens, for example on March 22 at 23:58, there are two renew entries in the DHCP logs shown below. One containing the IP of the Router (192.168.10.1)
Can someone tell me what might be going on.
TIA
Filtered by message containing 192.168.10.110.
Mar 23 06:57:53 dhcpd 51770 DHCPACK on 192.168.10.110 to 9c:53:22:08:9a:06 via re1 Mar 23 06:57:53 dhcpd 51770 DHCPREQUEST for 192.168.10.110 from 9c:53:22:08:9a:06 via re1 Mar 23 05:57:53 dhcpd 25371 DHCPACK on 192.168.10.110 to 9c:53:22:08:9a:06 via re1 Mar 23 05:57:53 dhcpd 25371 DHCPREQUEST for 192.168.10.110 from 9c:53:22:08:9a:06 via re1 Mar 23 04:57:53 dhcpd 25371 DHCPACK on 192.168.10.110 to 9c:53:22:08:9a:06 via re1 Mar 23 04:57:53 dhcpd 25371 DHCPREQUEST for 192.168.10.110 from 9c:53:22:08:9a:06 via re1 Mar 23 03:57:53 dhcpd 25371 DHCPACK on 192.168.10.110 to 9c:53:22:08:9a:06 via re1 Mar 23 03:57:53 dhcpd 25371 DHCPREQUEST for 192.168.10.110 from 9c:53:22:08:9a:06 via re1 Mar 23 02:57:53 dhcpd 25371 DHCPACK on 192.168.10.110 to 9c:53:22:08:9a:06 via re1 Mar 23 02:57:53 dhcpd 25371 DHCPREQUEST for 192.168.10.110 from 9c:53:22:08:9a:06 via re1 Mar 23 01:57:53 dhcpd 25371 DHCPACK on 192.168.10.110 to 9c:53:22:08:9a:06 via re1 Mar 23 01:57:53 dhcpd 25371 DHCPREQUEST for 192.168.10.110 from 9c:53:22:08:9a:06 via re1 Mar 23 00:57:53 dhcpd 25371 DHCPACK on 192.168.10.110 to 9c:53:22:08:9a:06 via re1 Mar 23 00:57:53 dhcpd 25371 DHCPREQUEST for 192.168.10.110 from 9c:53:22:08:9a:06 via re1 Mar 22 23:58:40 dhcpd 25371 DHCPACK on 192.168.10.110 to 9c:53:22:08:9a:06 via re1 Mar 22 23:58:40 dhcpd 25371 DHCPREQUEST for 192.168.10.110 (192.168.10.1) from 9c:53:22:08:9a:06 via re1 Mar 22 23:58:40 dhcpd 25371 DHCPOFFER on 192.168.10.110 to 9c:53:22:08:9a:06 via re1 Mar 22 23:52:52 dhcpd 25371 DHCPACK on 192.168.10.110 to 9c:53:22:08:9a:06 via re1 Mar 22 23:52:52 dhcpd 25371 DHCPREQUEST for 192.168.10.110 from 9c:53:22:08:9a:06 via re1 Mar 22 22:52:52 dhcpd 25371 DHCPACK on 192.168.10.110 to 9c:53:22:08:9a:06 via re1 Mar 22 22:52:52 dhcpd 25371 DHCPREQUEST for 192.168.10.110 from 9c:53:22:08:9a:06 via re1 Mar 22 21:52:52 dhcpd 25371 DHCPACK on 192.168.10.110 to 9c:53:22:08:9a:06 via re1 Mar 22 21:52:52 dhcpd 25371 DHCPREQUEST for 192.168.10.110 from 9c:53:22:08:9a:06 via re1 Mar 22 20:52:52 dhcpd 25371 DHCPACK on 192.168.10.110 to 9c:53:22:08:9a:06 via re1 Mar 22 20:52:52 dhcpd 25371 DHCPREQUEST for 192.168.10.110 from 9c:53:22:08:9a:06 via re1EDIT: Here is the unfiltered log. IP's that get disconnected are 192.168.10.90, 110, 130, 150
Mar 23 00:02:53 dhcp6c 74373 send renew to ff02::1:2%re0 Mar 23 00:02:53 dhcp6c 74373 set option request (len 4) Mar 23 00:02:53 dhcp6c 74373 set elapsed time (len 2) Mar 23 00:02:53 dhcp6c 74373 set identity association Mar 23 00:02:53 dhcp6c 74373 set IA address Mar 23 00:02:53 dhcp6c 74373 set server ID (len 26) Mar 23 00:02:53 dhcp6c 74373 set client ID (len 14) Mar 23 00:02:53 dhcp6c 74373 a new XID (def35d) is generated Mar 23 00:02:53 dhcp6c 74373 Sending Renew Mar 23 00:02:53 dhcp6c 74373 reset a timer on re0, state=RENEW, timeo=0, retrans=10068 Mar 23 00:02:53 dhcp6c 74373 IA timeout for NA-0, state=ACTIVE Mar 23 00:00:27 dhcpd 25371 DHCPACK on 192.168.10.20 to 90:0e:b3:fd:74:f9 via re1 Mar 23 00:00:27 dhcpd 25371 DHCPREQUEST for 192.168.10.20 from 90:0e:b3:fd:74:f9 via re1 Mar 23 00:00:25 dhcpd 25371 DHCPACK on 192.168.10.120 to 54:2a:1b:dd:f2:b4 via re1 Mar 23 00:00:25 dhcpd 25371 DHCPREQUEST for 192.168.10.120 from 54:2a:1b:dd:f2:b4 via re1 Mar 22 23:58:40 dhcpd 25371 DHCPACK on 192.168.10.140 to d8:44:89:ab:7d:1e via re1 Mar 22 23:58:40 dhcpd 25371 DHCPREQUEST for 192.168.10.140 (192.168.10.1) from d8:44:89:ab:7d:1e via re1 Mar 22 23:58:40 dhcpd 25371 DHCPOFFER on 192.168.10.140 to d8:44:89:ab:7d:1e via re1 Mar 22 23:58:40 dhcpd 25371 DHCPDISCOVER from d8:44:89:ab:7d:1e via re1 Mar 22 23:58:40 dhcpd 25371 DHCPACK on 192.168.10.90 to 5c:62:8b:6e:5c:fc via re1 Mar 22 23:58:40 dhcpd 25371 DHCPREQUEST for 192.168.10.90 (192.168.10.1) from 5c:62:8b:6e:5c:fc via re1 Mar 22 23:58:40 dhcpd 25371 DHCPOFFER on 192.168.10.90 to 5c:62:8b:6e:5c:fc via re1 Mar 22 23:58:40 dhcpd 25371 DHCPDISCOVER from 5c:62:8b:6e:5c:fc via re1 Mar 22 23:58:40 dhcpd 25371 DHCPACK on 192.168.10.130 to c8:db:26:0c:60:7f via re1 Mar 22 23:58:40 dhcpd 25371 DHCPREQUEST for 192.168.10.130 from c8:db:26:0c:60:7f via re1 Mar 22 23:58:40 dhcpd 25371 DHCPACK on 192.168.10.110 to 9c:53:22:08:9a:06 via re1 Mar 22 23:58:40 dhcpd 25371 DHCPREQUEST for 192.168.10.110 (192.168.10.1) from 9c:53:22:08:9a:06 via re1 Mar 22 23:58:40 dhcpd 25371 DHCPOFFER on 192.168.10.110 to 9c:53:22:08:9a:06 via re1 Mar 22 23:58:40 dhcpd 25371 DHCPDISCOVER from 9c:53:22:08:9a:06 via re1 Mar 22 23:58:25 dhcpd 25371 DHCPACK on 192.168.10.150 to 34:98:7a:ec:11:6d via re1 Mar 22 23:58:25 dhcpd 25371 DHCPREQUEST for 192.168.10.150 (192.168.10.1) from 34:98:7a:ec:11:6d via re1 Mar 22 23:58:25 dhcpd 25371 DHCPOFFER on 192.168.10.150 to 34:98:7a:ec:11:6d via re1 Mar 22 23:58:25 dhcpd 25371 DHCPDISCOVER from 34:98:7a:ec:11:6d via re1 Mar 22 23:57:53 dhcp6c 74373 got an expected reply, sleeping. Mar 22 23:57:53 dhcp6c 74373 removing an event on re0, state=RENEW Mar 22 23:57:53 dhcp6c 74373 script "/var/etc/dhcp6c_wan_script.sh" terminated Mar 22 23:57:53 dhcp6c 10104 dhcp6c renew, no change - bypassing update on re0 -
@gregeeh I saw that sort of repetition when testing Kea early, but it was fixed in 2.7.2:
https://docs.netgate.com/pfsense/en/latest/releases/2-7-2.html#dhcp-ipv4If using Kea you could switch back to the (stable) ISC DHCP.
People may also point out Realtek isn’t well liked on this forum.
Pre-2.7.2/23.09: Only install packages for your version, or risk breaking it. Select your branch in System/Update/Update Settings.
When upgrading, allow 10-15 minutes to restart, or more depending on packages and device speed.
Upvote 👍 helpful posts! -
@SteveITS said in Please explain these log messages:
If using Kea you could switch back to the (stable) ISC DHCP.
Thanks for your reply. But using ISC DHCP in this case.
-
@gregeeh
Are you sure you don’t have any "friendly" neighbors who might be sending management frames on behalf of your wireless network SSID?
And yes... Are you sure you have the latest realtek driver installed? -
@w0w said in Please explain these log messages:
Are you sure you don’t have any "friendly" neighbors who might be sending management frames on behalf of your wireless network SSID?
As I live in a Retirement Village,I do not think anyone here would have that knowledge.
@w0w said in Please explain these log messages:
Are you sure you have the latest realtek driver installed?
I think so, but I will double check.
EDIT:
Version 1.98. I think that is the latest. -
@gregeeh
What access point is being used? Does it have logs? -
It's not kea, its :
The DHCP server received a request, and it send a reply. So, on the pfSense side of things, all is fine.
A DHCP request for renew, is received by pfSense, and ACK and eventually OFFERS are send.
Clear enough, the device requesting the DHCP leases never received the pfSense DHCP reply.
If this was a cabled device : routing problem ? Or probably a bad cable.
Wifi ? don't look any further : the wifi AP received the request over radio just fine, send the request over cable t pfSense, got the reply back, but the last part, radio again, never made it to the requesting device.
Keep in mind : it isn't because we can "see" neither "feel" radio signals, that this does mean they are perfect. The contrary is actually true : it's loaded with static noise, other devices that send out harmonics using the same frequency; leaking microwave ovens ( ! ), other APs that are using the same channel (= frequency), stupid IOT devices that broadcast without sensing if the channel is free, etc etc.
Check with the concerned AP if it can tell you if other APs are around it using the same frequency. Check if there are devices connected over wifi that have many retries == bad connection. etc. -
@Gertjan - Thanks for your great detailed reply. It's appreciated.
I think you might be correct about other AP's using the same frrequency. I've been trying channels 1 & 6 previously and have just changed it to Channel 13 to test for a couple of days.
As it only affects devices on the 2.4GHz Radio and all at the same time it maybe interference from other AP's. I'm using a Unifi AC-Lite at the moment and don't know if it can tell me if there are any other AP's using the same frequency. However I did install a WiFi Analyser on my phone and those popular channels (1, 6, & 11) do have more activity.
I have also changed the DHCP lease time from 2 Hours to 7 Days, thinking that might help too.
Thanks again.
Greg
-
@gregeeh said in Please explain these log messages:
I'm using a Unifi AC-Lite at the moment and don't know if it can tell me if there are any other AP's using the same frequency.
I'm using the Unifi controller for this.
@gregeeh said in Please explain these log messages:
I have also changed the DHCP lease time from 2 Hours to 7 Days, thinking that might help too.
Probably not.
Wifi devices tend to go out of range and come back into range continuously. The wifi interface keeps on getting down and up again: this starts a DHCP sequence. -
Obviously this may not aid your quest at all, but I shall share my possibly similar story that took me several months to finally nail down.
Involved: HomeAssistant, TPLink/wifi light switches, TPLink Archer AX3000 wifi router in AP mode.
So Homeassistant would log 2 devices going unavailable approximately every 9 minutes and 12 seconds. There would be variation on occasion....but 9:12 / 9:10 / 9:15 around that timeframe. All the time.
It got to the point that I would doubletap any commands coming from homeassistant to the devices. An an off/on/dimm function would frequently land during the unavailable time.
DHCP logs in pfsense looked just fine, very similar to yours. req/acks just fine.
The light switches didn't ~seem~ to be doing a reboot of any type. The firmware inside those things is naturally always sus, but I could sit and watch it and wait for the light to turn red, and one would imagine that pressing a button just then wouldn't work if the switch itself was rebooting. The switch always worked.
I moved the AP. I updated firmwares. Changed channels. Changed channel settings. I lost my mind.
Finally broke down and bought an ASUS ZenWifi XT9 AP set. Instantly fixed. No dropouts ever.
Completely unproven working theories:
-Because of the dual AP with 5Ghz backbone link between them one AP could in fact sit approximately 3 feet and 5 feet closer to each of the sus switches.
-TP just plain sucks anyway...probably the AP fault...momentary delays in processing frames was my go to excuse.
-Asus hardware is generally more respected and stable...just works better?
-a single less structural element between the devices - 1 wall in 1 direction, 1 floor in the other.So what I suggest:
Tweak those signals. Move the AP, tweak the antennas, change channels and power levels.Also you say randomly .... microwave ovens nearby? Your neighbor making popcorn...the the staff lounge next door?
Because the XT9s have an annoying habit of moving the backhaul data to the 2.4Ghz becuase suddenly deciding the upper 5Ghz band is less db than the 2.4Ghz.... I've lowered the 2.4Ghz to minimum power levels and the switches still do not disconnect. Sometimes less power is cleaner rf power.
Borrow some other AP and clone the settings from your old one. See if things disconnect still. Might help determine if it is worth it to swap devices permanently.
(edited caveat -- Yes...I say upper 5Ghz band. It isn't 6Ghz. I hate marketing people with the fire of a thousand suns. Sure there are some 6Ghz channels in the standard...but I'm not using them and I appreciate the XT9 interfaces actually say 5Ghz-2 .... they don't round up.)
-
@skogs - Many thanks for you comments, it's most appreciated.
Recently I have written a script that pings the failing devices every 15 secs and logs the failures and when the connection returns. There's no pattern, unlike yourself, but they generally all fail, and communications return, at the same time which does sound like a network issue of some sort as I would not expect all the devices to intermittently fail at the same time. These disconnects and connects are also seen in the Unifi Network Application.
My present AP is an 8 year old Unifi AC-Lite and I'm going to take your advise and temporarily replace it with a Modem/Router in AP Mode that I have in the cupboard. It's not a new device but it will hopefully shine some light on the issue, one way or another.
My other option is just replace the AC-Lite with the Unifi 6 Plus.
Thanks once again for your input.
Greg
