Solved Wrong IPs shown on "Wireless Log" webpage.

[Martinski]

UPDATE:

I have verified that the problems described/reported in the 1st post of this thread have been completely fixed in Asuswrt-Merlin 386.7_0 version, released 2022-June-22.
Just FYI.

==============================================
Last evening we went to visit a family member and after we had dinner, I took some time to do maintenance on their RT-AC86U running AsusWRT-Merlin 386.4_0 version. I also moved some new surveillance cameras (that they had already installed around the house) into a separate 2.4GHz Guest network that was created specifically for IoT devices (on a separate subnet with IP address reservations and client isolation). After the setup was completed and while every wireless device was methodically being reconfigured, rebooted, and reconnected, I checked the current list of clients shown on the YazFi GUI panel, and the one shown on the "Wireless Log" GUI panel, and I found that there were 2 discrepancies in the IP address assignments being displayed:

  Client MAC         WiFi Band     Correct IP          Wrong IP
-----------------   -----------  ---------------    ---------------
xx:xx:xx:D9:6A:48     2.4 GHz     172.26.225.32      172.25.250.36
xx:xx:xx:F6:8D:45     5.0 GHz     172.27.225.38      172.25.250.53

So I began to double-check the network configuration and looked at the various places where IP address assignments are listed, and I found that the following places were showing the correct list of IPs for all connected clients:

- The "Guest Network" --> "YazFi" GUI panel (see screenshot)
- The "System Log" --> "DHCP Leases" GUI panel.
- The "/var/lib/misc/dnsmasq.leases" file.
- The results of the "arp" command (see screenshot)

However, the "System Log" --> "Wireless Log" GUI panel continued to show the 2 incorrect IP address assignments (see screenshots). The wrong IPs being displayed are for the Main Network (172.25.250.*), and not for the Guest Network subnets as expected (172.26.225.* & 172.27.225.* for the 2.4GHz & 5GHz bands, respectively). Also note that the wrong IPs were actually not being used at all by any client, wired or wireless.

I've attached to this post 4 screenshots: the ones that displayed the wrong IPs, and the others that showed the correct IPs (which also match the IP address reservations previously set up in the "dnsmasq.conf.add" file).

"Wireless Log" GUI Panel:

BTW, functionally everything was (and continues to be) working fine in all 3 networks (Main LAN/WLAN, 2.4GHz & 5GHz Guest WLANs). I even double-checked each individual client (a surveillance camera & an iPad) that had the "wrong IP address" displayed, and they themselves show the correct IP assignment. So these "IP address errors" appear to be only a "GUI display" problem. Functionally, all clients are OK and working well, as far as we could ascertain. There are no other routers or APs or AiMesh nodes in the network; it's a single router with 2 unmanaged switches connected (one located in the living room, and another one in the master bedroom), and a number of devices in the home are wired via CAT6 cables (2 mini PCs, 3 laptops, 1 NAS, 1 Linux file server).

Bottom line, to me this means that the information presented in the "Wireless Log" GUI panel may not always be as reliable as I thought it was.

 

[alan6854321]

Yeah - I've noticed this before.
I did raise it on the 'YazFi' thread but no one seemed much interested.

I think what happens is that clients connect to WiFi before YazFi gets started - so they get an IP address from the 'main' network.

YazFi then throws them off ("Forcing YazFi Guest WiFi clients to reauthenticate" message in syslog) and they reconnect and get their 'guest' IP address.

But the wireless log doesn't seem to get updated.

 

[Martinski]

I think what happens is that clients connect to WiFi before YazFi gets started - so they get an IP address from the 'main' network.

This is not possible in the case of the surveillance camera showing the wrong IP address. Each camera was reset to factory defaults, and then re-configured manually to connect ONLY to the 2.4GHz Guest network (i.e. the one for "IoT Devices"), so they don't have the SSID & login password to be able to connect to the Main network if they wanted to, or even by accident. And yes, we did verify that none of the cameras could connect to the Main network after being reset to factory defaults. In addition, the router was rebooted after the Guest network was re-configured for IoT devices, so all the DHCP leases were (and should be) renewed from scratch, including the IP address reservations.

In the case of the iPad on the 5GHz Guest network, I suppose your theory it's a possible explanation since the iPad does have the login credentials for both the Main & Guest networks.

BTW, we considered moving the Guest networks to the #2 slots (middle column) to avoid any issues related to AiMesh that have been reported with the #1 slots (far left column), but since the clients were actually running well and had no issues WRT their functionality, we decided to leave things as they were. We may revisit this option if we see problems in the future.

In any case, since by all indications the errors appear to be only a "Wireless Log" GUI display problem, and the wireless clients are in fact running with their correctly assigned IP address, I'm not really worried about it. But it's something to be aware of, and I'll keep an eye on it.

Thanks.

 

[alan6854321]

Each camera was reset to factory defaults, and then re-configured manually to connect ONLY to the 2.4GHz Guest network (i.e. the one for "IoT Devices"), so they don't have the SSID & login password to be able to connect to the Main network if they wanted to, or even by accident.

No, that's no quite what I meant.

The devices will always connect using the 'guest' credentials, but initially (e.g. immediately after rebooting the router) dnsmasq hasn't been setup to allocate the 'guest' IP address range yet.

Once YazFi has done it stuff, dnsmasq will be configured to allocate the 'guest' IP addresses to that network.

YazFi then throws any already-connected clients off so they reconnect and get new addresses.

 

[Martinski]

The devices will always connect using the 'guest' credentials, but initially (e.g. immediately after rebooting the router) dnsmasq hasn't been setup to allocate the 'guest' IP address range yet.

Once YazFi has done it stuff, dnsmasq will be configured to allocate the 'guest' IP addresses to that network.

I'm afraid I don't really quite understand your theory. Are you basically saying that any Guest Network client may be able to get an IP address assigned and then connect to the network even *before* the 'dnsmasq' service is fully operational with the finalized Guest Network DHCP setup?

AFAIK, once the Guest Networks have been configured via the GUI (first with the built-in GUI, and then with the "YazFi" GUI - if such Add-On has been installed), the DHCP configuration for each Guest Network can be essentially modified and finalized via the "dnsmasq.conf.add" & "dnsmasq.postconf.sh" files (if found).

My understanding of the sequence of events for 'dnsmasq' during a reboot is as follows (in very broad strokes):

1) The system automatically generates the "/tmp/etc/dnsmasq.conf" file.
2) If found, "/jffs/configs/dnsmasq.conf.add" is appended to "/tmp/etc/dnsmasq.conf"
3) If found, "/jffs/scripts/dnsmasq.postconf.sh" script starts executing in blocking mode.
4) If found, "/jffs/addons/YazFi.d/.dnsmasq" file is appended to "/tmp/etc/dnsmasq.conf"
5) The "/jffs/scripts/dnsmasq.postconf.sh" script terminates and returns (if called to execute).
6) The 'dnsmasq' service is started & initialized using the (now possibly modified) "/tmp/etc/dnsmasq.conf" file.

AFAIK, *before* the 'dnsmasq' service is started and is fully operational (last step above), no client (wired or wireless) can connect at all to any of the networks. IOW, no client could ever connect to the Main or Guest networks until dnsmasq has been fully initialized, at which point the Guest Network DHCP configuration settings (e.g. "interface=wl0.1", "dhcp-range=wl0.1,...", "dhcp-option=wl0.1,3,....", "dhcp-option=wl0.1,6,....") are now embedded in the "/tmp/etc/dnsmasq.conf" file.

Unless I'm mistaken and my understanding is completely wrong, or there's a serious bug in the system WRT the 'dnsmasq' service, what I think you described should not happen. So I guess what you're saying is that there might be a bug somewhere in the 'dnsmasq' service initialization sequence?

 

[alan6854321]

Are you basically saying that any Guest Network client may be able to get an IP address assigned and then connect to the network even *before* the 'dnsmasq' service is fully operational with the finalized Guest Network DHCP setup?

yes, sort of.

Not before dnsmasq is operational, but before YazFi has setup it's configuration.

Right now , I have had many beers, we really need @Jack Yaz to comment.

 

[Jack Yaz]

yes, sort of.

Not before dnsmasq is operational, but before YazFi has setup it's configuration.

Right now , I have had many beers, we really need @Jack Yaz to comment.

YazFi starts with the firewall and kicks clients off the WiFi radios to force a reauth. If that's not happening then let me know

 

[alan6854321]

YazFi starts with the firewall and kicks clients off the WiFi radios to force a reauth. If that's not happening then let me know

Yes, that IS happening.

But the effect of that is that some clients have already connected and received IP addresses on the main network before being kicked off by YazFi and then getting their guest IP addresses.

The wireless log page doesn't seem to get updated with the new addresses and still shows devices which are connected to the guest network with main network addresses. Seems to happen at random.

Everything seems to work as expected except the wireless log page shows incorrect info.

 

[bennor]

But the effect of that is that some clients have already connected and received IP addresses on the main network before being kicked off by YazFi and then getting their guest IP addresses.

I ran into something somewhat similar with certain IoT devices (primarily Amazon Echo's). The issue in my case stemmed from the fact that the IoT device was saving the WiFi login for each WiFi network it was connected to. So if I ever connected them to the main WiFi network before joining them to the YazFi Guest WiFi network they would default to the main WiFi network first. I had to go into the app and the online portal for the IoT device and delete all saved WiFi entries. Then setup one single entry connection to just the YazFi Guest WiFi. A simple IoT device reset wouldn't work since it kept pulling in the saved WiFi information once reconnected to YazFi Guest WiFi. Drove me nuts trying to figure out why it kept pulling the wrong IP address. Clearing out all the saved WiFi login information is what fixed it on those devices.

 

[Martinski]

Yes, that IS happening.

But the effect of that is that some clients have already connected and received IP addresses on the main network before being kicked off by YazFi and then getting their guest IP addresses.

Is this still just a personal theory at this point? Or, have you actually seen system logs that show a Guest Network client getting an IP address from the Main Network IP range *before* "being kicked off by YazFi" and finally getting the expected IP address from the Guest Network?

If you have such logs, would you mind sharing them on this thread?

So far, I have not seen that particular scenario happened with my router, or my family member's routers (all RT-AC86U models running AsusWRT-Merlin f/w). And I cannot explain why sometimes the "System Logs" information WRT Guest Network client IP assignments is incorrect.

AFAICT, during reboot, by the time the dnsmasq service is started & fully operational, all necessary DCHP settings for the Guest Networks (as pre-configured via YazFi) have already been appended to the "/tmp/etc/dnsmasq.conf" file - see step #4 described in post #5 of this thread.

IOW, *before* the dnsmasq service has been started & becomes fully operational, the contents of the "/jffs/addons/YazFi.d/.dnsmasq" file is appended to the "/tmp/etc/dnsmasq.conf" file (during "/jffs/scripts/dnsmasq.postconf" script execution). This means that once dnsmasq service has actually started, it's got all the required DHCP configuration settings so that each Guest Network client should get its own IP address from the correct IP range, *not* from the Main Network; unless, of course, there's a bug somewhere in how IP addresses get assigned during reboot.

I'm not saying that such a bug cannot or does not exist; just that, so far, I have not seen any evidence that points to it as an explanation for the "System Logs" GUI display problem.

 

[alan6854321]

Is this still just a personal theory at this point?

Just a theory, I guess, but it would explain the problem!

Unfortunately, I don't have a syslog file that goes back as far the last reboot at the moment.

What I can remember though, is seeing is some syslog messages where a device connects to the guest network, tries to use a main network address and gets rejected.

This is immediately after being "kicked off" by YazFi.

The messages look something like this ....
dnsmasq-dhcp[3055]: DHCPNAK(wl0.2) 192.168.1.43 FF:FF:FF:FF:FF:FF wrong network

The device should be using a 192.168.3.nnn type address (And indeed does after this).

 

[Martinski]

The messages look something like this ....
dnsmasq-dhcp[3055]: DHCPNAK(wl0.2) 192.168.1.43 FF:FF:FF:FF:FF:FF wrong network

OK, I believe I understood your perspective. Next time I get a chance to reboot one of the routers, I'll review the system logs immediately after and will run a specific search for those kinds of messages:
"dnsmasq-dhcp[*]: DHCPNAK(*) ..."

Thanks.

 

[alan6854321]

OK - new release - router rebooted!!!

This is a grep from the syslog after the reboot.
18:69:d8:60:d5:51 is an IoT device (A smartplug)
I've added the YazFi reauthenticate line so you can see where it occurs.

The error message seems to have changed from "wrong network" to "wrong server-ID", don't know if that happened with this new release or what.

The first two line have a strange date/time - I think that's some kind of default before the proper time gets set.

grep -i 18:69:d8:60:d5:51 syslog1.txt

May  5 06:05:11 wlceventd: wlceventd_proc_event(527): wl0.2: Auth 18:69:D8:60:D5:51, status: Successful (0), rssi:0
May  5 06:05:11 wlceventd: wlceventd_proc_event(556): wl0.2: Assoc 18:69:D8:60:D5:51, status: Successful (0), rssi:0
Mar  3 09:26:23 dnsmasq-dhcp[1969]: DHCPDISCOVER(br0) 18:69:d8:60:d5:51
Mar  3 09:26:23 dnsmasq-dhcp[1969]: DHCPOFFER(br0) 192.168.1.132 18:69:d8:60:d5:51

Mar  3 09:26:41 YazFi: Forcing YazFi Guest WiFi clients to reauthenticate ====== Happens here

Mar  3 09:26:41 wlceventd: wlceventd_proc_event(508): wl0.2: Disassoc 18:69:D8:60:D5:51, status: 0, reason: Disassociated because sending station is leaving (or has left) BSS (8), rssi:0
Mar  3 09:26:48 dnsmasq-dhcp[2909]: DHCPREQUEST(br0) 192.168.1.132 18:69:d8:60:d5:51
Mar  3 09:26:48 dnsmasq-dhcp[2909]: DHCPACK(br0) 192.168.1.132 18:69:d8:60:d5:51 SmartOfficeHeater
Mar  3 09:26:48 dnsmasq-dhcp[2909]: DHCPREQUEST(wl0.2) 192.168.1.132 18:69:d8:60:d5:51
Mar  3 09:26:48 dnsmasq-dhcp[2909]: DHCPNAK(wl0.2) 192.168.1.132 18:69:d8:60:d5:51 wrong server-ID
Mar  3 09:26:59 wlceventd: wlceventd_proc_event(527): wl0.2: Auth 18:69:D8:60:D5:51, status: Successful (0), rssi:0
Mar  3 09:26:59 wlceventd: wlceventd_proc_event(556): wl0.2: Assoc 18:69:D8:60:D5:51, status: Successful (0), rssi:0
Mar  3 09:27:20 dnsmasq-dhcp[2909]: DHCPDISCOVER(wl0.2) 18:69:d8:60:d5:51
Mar  3 09:27:20 dnsmasq-dhcp[2909]: DHCPOFFER(wl0.2) 192.168.3.110 18:69:d8:60:d5:51
Mar  3 09:27:20 dnsmasq-dhcp[2909]: DHCPDISCOVER(wl0.2) 18:69:d8:60:d5:51
Mar  3 09:27:20 dnsmasq-dhcp[2909]: DHCPOFFER(wl0.2) 192.168.3.110 18:69:d8:60:d5:51
Mar  3 09:27:20 dnsmasq-dhcp[2909]: DHCPDISCOVER(wl0.2) 18:69:d8:60:d5:51
Mar  3 09:27:20 dnsmasq-dhcp[2909]: DHCPOFFER(wl0.2) 192.168.3.110 18:69:d8:60:d5:51
Mar  3 09:27:20 dnsmasq-dhcp[2909]: DHCPDISCOVER(wl0.2) 18:69:d8:60:d5:51
Mar  3 09:27:20 dnsmasq-dhcp[2909]: DHCPOFFER(wl0.2) 192.168.3.110 18:69:d8:60:d5:51
Mar  3 09:27:20 dnsmasq-dhcp[2909]: DHCPDISCOVER(wl0.2) 18:69:d8:60:d5:51
Mar  3 09:27:20 dnsmasq-dhcp[2909]: DHCPOFFER(wl0.2) 192.168.3.110 18:69:d8:60:d5:51
Mar  3 09:27:20 dnsmasq-dhcp[2909]: DHCPREQUEST(wl0.2) 192.168.3.110 18:69:d8:60:d5:51
Mar  3 09:27:20 dnsmasq-dhcp[2909]: DHCPACK(wl0.2) 192.168.3.110 18:69:d8:60:d5:51 SmartOfficeHeater

 

[Martinski]

OK - new release - router rebooted!!!

This is a grep from the syslog after the reboot.
18:69:d8:60:d5:51 is an IoT device (A smartplug)
...

Well, that was intriguing. Why would dnsmasq attempt to assign to the device an IP address from the Main Network IP range before finally giving it the expected IP address from the Guest Network?

I understand the step when YazFi needs to re-authenticate all the Guest Network clients after it gets called to run via the "firewall-start" script; however, before that happens I would have expected the dnsmasq service to have been already started/initialized and to have all the required DHCP settings when both "dnsmasq.conf.add" & "dnsmasq.postconf" were invoked during reboot.

Perhaps my understanding is incorrect or incomplete because the sequence of events seems to be different from what I have observed before.

Does your IoT device have a manually assigned IP address set up either via the device itself as a static IP, or via a DHCP IP address reservation list?

I'll review my own system logs after rebooting the router next time; I really need to see more context of when certain events happen during a reboot. Unfortunately, I'll be busy this coming weekend, which is when I usually take the time to update F/W (when needed) and do maintenance.

Thanks for the additional information.

 

[alan6854321]

Does your IoT device have a manually assigned IP address set up either via the device itself as a static IP, or via a DHCP IP address reservation list?

No, all the IoT devices on the guest network just use dynamic addresses.

I do have some devices (nas, raspi's etc) that have manual or static addresses, but they're all on the main network.

 

[alan6854321]

Something I didn't mention before, that device I posted the syslog's for (18:69:d8:60:d5:51) showed exactly the issue we're talking about on the router UI.

Wireless log showed 192.168.1.132
DHCL Leases log showed 192.168.3.110

 

[Martinski]

No, all the IoT devices on the guest network just use dynamic addresses.

I do have some devices (nas, raspi's etc) that have manual or static addresses, but they're all on the main network.

Noted. Thanks.

 

[ColinTaylor]

@Martinski The wireless log page tries to determine the IP address of the client by looking for a matching MAC address in the arp table and DHCP lease file. The code is here.

Essentially it is using the output from these commands:

cat /proc/net/arp
cat /var/lib/misc/dnsmasq.leases

I'm not in a position to try to recreate this problem but I suspect that issue is that the /proc/net/arp file still contains a matching MAC address associated with the old IP address. A simple user arp command would not show these MAC addresses because the flag value would cause them to be replaced with <incomplete>, but they're still there.

 

[alan6854321]

@ColinTaylor , @Martinski , I checked the arp table for inconsistent entries, it contains both addresses allocated to the device.

The first (With device 'br0') is the original, incorrect address
The second (With device 'wl0.2') is the new, correct address.

grep 8e:e2 /proc/net/arp
192.168.1.214    0x1         0x0         18:69:d8:65:8e:e2     *        br0
192.168.3.165    0x1         0x2         18:69:d8:65:8e:e2     *        wl0.2

 

[Martinski]

@Martinski The wireless log page tries to determine the IP address of the client by looking for a matching MAC address in the arp table and DHCP lease file. The code is here.

Essentially it is using the output from these commands:

cat /proc/net/arp
cat /var/lib/misc/dnsmasq.leases

Thank you!!

Yes, that code first parses the contents of /proc/net/arp (line by line, top to bottom) until it finds the 1st instance of the MAC address being searched, completely ignoring the flag in that same line that indicates whether the entry is in fact "complete." The code then skips the rest of the table.

If the line containing the correct IP address associated with the MAC address is found first (before any other possible lines with incorrect IPs), the current code works as it is today. However, if the first match of the MAC address happens to have the incorrect IP address, the wrong information ends up being shown in the "Wireless Log" webpage.

The fix is fairly simple: modify the "if-then" conditional statement (specifically, lines #511-#512 in the current source code) to get the flag and check it for a non-zero value; when all conditions are true, skip the rest of the table like before.

FROM current code:

...
if ( (sscanf(line,"%15s %*s %*s %17s",ipentry,macentry) == 2) &&
     (!strcasecmp(macentry, ether_etoa((void *)&auth->ea[i], ea))) ) {
    found = 1;
    break;
} else
...

TO fixed code:

/* to parse & ignore "incomplete" entries */
unsigned int flagentry = 0;

...
if ( (sscanf(line, "%15s %*s %x %17s", ipentry, &flagentry, macentry) == 3) &&
     (!strcasecmp(macentry, ether_etoa((void *)&auth->ea[i], ea))) &&
     (flagentry != 0) ) {
    found = 1;
    break;
} else
...

The question remains as to why sometimes the arp table still contains the additional entry with the same MAC address being associated with the incorrect IP address.

In any case, the flag value clearly indicates which entry is the correct one so the solution to the "Wireless Log" webpage showing incorrect IP information is simple, IMO.

Thanks again.

EDIT:
I just realized that I should probably tag @RMerlin here to see if he agrees with the code modifications I have proposed above, assuming my analysis of the situation was correct. And if so, he could make the changes for the next release whenever he gets a chance (with the assumption that he has full control over that source code).