Hello, I'm using an IAP-215 and am having some strange occurences show up in my AP logs with a client (logs are attached).
DHCP server is configured to be running on the AP so it is handing out IP addresses. DHCP pool has a subnet of 192.168.22.xxx.
When the client first connects to the AP, the proper DHCP handshake sequence begins (time stamp: Nov 22 07:18:12) and a user entry is created for the client with an IP address of 192.168.22.214 in this particular example.
However at some point, the client's IP address is changed without the lease time being reached or any DHCP DISCOVER or RENEW handshake. The new IP address is 192.168.5.1 not in the DHCP pool. As a note, this address is always 192.168.5.1 even outside of this specific example.
At a later point, the IP address reverts back to the 192.168.22.214 address.
This happens several times (example below for timestamp Nov 22 07:24:14):
Nov 22 07:24:14 2016 192.168.4.30 stm[3448]: <304008> <DBUG> <192.168.4.30 F0:5C:19:C0:95:AC> |ap| user ip:192.168.5.1 mac:00:0e:8e:67:09:eb
Nov 22 07:24:14 2016 192.168.4.30 <192.168.4.30 F0:5C:19:C0:95:AC> stm[3448]: rap_bridge_user_handler: 13806: rbs update: flags:1/1 aclnum:130 ip:192.168.5.1 mac:00:0e:8e:67:09:eb bssid:f0:5c:19:89:5a:d0 vlan:1 wired:0
Nov 22 07:24:14 2016 192.168.4.30 stm[3448]: <501200> <DBUG> <192.168.4.30 F0:5C:19:C0:95:AC> Rap bridge user msg, flags-1 action-1 aclnum-130 ip-192.168.5.1 mac-00:0e:8e:67:09:eb,bssid-f0:5c:19:89:5a:d0 vlan-1 wired-0
Nov 22 07:24:14 2016 192.168.4.30 stm[3448]: <501216> <NOTI> <192.168.4.30 F0:5C:19:C0:95:AC> rap_bridge_user_handler 13824: user entry created for 192.168.5.1-00:0e:8e:67:09:eb
Nov 22 07:24:14 2016 192.168.4.30 <192.168.4.30 F0:5C:19:C0:95:AC> stm[3448]: rap_bridge_user_handler: 13826: user entry created for '192.168.5.1' '00:0e:8e:67:09:eb'
Nov 22 07:24:14 2016 192.168.4.30 stm[3448]: <304008> <DBUG> <192.168.4.30 F0:5C:19:C0:95:AC> |ap| rap_bridge_user_handler: ip is 192.168.5.1, flag=1!!
Nov 22 07:24:14 2016 192.168.4.30 stm[3448]: <304008> <DBUG> <192.168.4.30 F0:5C:19:C0:95:AC> |ap| bridge_users_sync: Value of the rap_bridge_user flag is 1
Nov 22 07:24:14 2016 192.168.4.30 cli[3412]: <541024> <DBUG> <192.168.4.30 F0:5C:19:C0:95:AC> recv_user_sync_message,7903:get sync message for client 00:0e:8e:67:09:eb, from 127.0.0.1
Nov 22 07:24:14 2016 192.168.4.30 cli[3412]: <341001> <DBUG> <192.168.4.30 F0:5C:19:C0:95:AC> DDNS: Delete user for IP 192.168.22.214
Nov 22 07:24:14 2016 192.168.4.30 cli[3412]: <541031> <INFO> <192.168.4.30 F0:5C:19:C0:95:AC> Learning client username: mac-00:0e:8e:67:09:eb usr-E0954 acct-E0954.
Nov 22 07:24:14 2016 192.168.4.30 stm[3448]: <304008> <DBUG> <192.168.4.30 F0:5C:19:C0:95:AC> |ap| user ip:192.168.22.214 mac:00:0e:8e:67:09:eb
Nov 22 07:24:14 2016 192.168.4.30 <192.168.4.30 F0:5C:19:C0:95:AC> stm[3448]: rap_bridge_user_handler: 13806: rbs update: flags:1/1 aclnum:130 ip:192.168.22.214 mac:00:0e:8e:67:09:eb bssid:f0:5c:19:89:5a:d0 vlan:1 wired:0
Nov 22 07:24:14 2016 192.168.4.30 stm[3448]: <501200> <DBUG> <192.168.4.30 F0:5C:19:C0:95:AC> Rap bridge user msg, flags-1 action-1 aclnum-130 ip-192.168.22.214 mac-00:0e:8e:67:09:eb,bssid-f0:5c:19:89:5a:d0 vlan-1 wired-0
Nov 22 07:24:14 2016 192.168.4.30 stm[3448]: <501216> <NOTI> <192.168.4.30 F0:5C:19:C0:95:AC> rap_bridge_user_handler 13824: user entry created for 192.168.22.214-00:0e:8e:67:09:eb
Nov 22 07:24:14 2016 192.168.4.30 <192.168.4.30 F0:5C:19:C0:95:AC> stm[3448]: rap_bridge_user_handler: 13826: user entry created for '192.168.22.214' '00:0e:8e:67:09:eb'
Nov 22 07:24:14 2016 192.168.4.30 stm[3448]: <304008> <DBUG> <192.168.4.30 F0:5C:19:C0:95:AC> |ap| rap_bridge_user_handler: ip is 192.168.22.214, flag=1!!
Nov 22 07:24:14 2016 192.168.4.30 stm[3448]: <304008> <DBUG> <192.168.4.30 F0:5C:19:C0:95:AC> |ap| bridge_users_sync: Value of the rap_bridge_user flag is 1
Nov 22 07:24:14 2016 192.168.4.30 cli[3412]: <541024> <DBUG> <192.168.4.30 F0:5C:19:C0:95:AC> recv_user_sync_message,7903:get sync message for client 00:0e:8e:67:09:eb, from 127.0.0.1
Nov 22 07:24:14 2016 192.168.4.30 cli[3412]: <341001> <DBUG> <192.168.4.30 F0:5C:19:C0:95:AC> DDNS: Delete user for IP 192.168.5.1
This usually only lasts for a second or two, but I have seen several cases where it ends up being significantly longer. In the attached log there is one case where the whole exchange occurs over 28 seconds (Nov 22 07:31:35).
Why would the IP address for a client change without a DHCP DISCOVER/RENEW? Why would it show up as an IP address that is not part of the DHCP pool? Is this a potential bug?
Now this could also be due to something on the client side. When investigating on the client side I opened a TCP dump on the network and noticed some peculiarities on this side.
I setup a ping from the system to the wireless adapter on client. From the TCP dump the ping leaves via the AP and the response comes back from the 192.168.22.214 address.
However, when the client is connected via a wired port, the pings leaves via the AP (confirmed with Omnipeek), but the TCP dump now shows pings returning over the wire with a 192.168.5.1 address. I checked and this looked to be the address of the ethernet port the client connected to.
When the client was disconnected from the wire, I stopped hearing ping responses from both the 192.168.22.214 and the 192.168.5.1 address in the TCP dump. About 10 seconds later, I see responses finally coming back from the 192.168.22.214 address.
So it looks like the client automatically routes any traffic (even communication the comes from wireless) down the wired address if possible. When disconnected, it takes a while for the client to figure out that it needs to re-route back to the wireless.
How does the AP client table determine what the IP address of the client is? Would this network traffic switching from the client be the cause of the of the AP changing the IP address of the client?
Sorry about the long and convuluted scenario and thanks for taking a look at this.