Menu
▾
▴
Re: [PacketFence-users] Default Network Detection failure after RADIUS Disconnect from Captive Portal
|
From: Ian M. <im...@ne...> - 2023-01-27 16:53:36
|
After some testing with IOS 16.0 on an iPhone 12 Pro, we learned a couple of additional things, that also helped explain some of our early test cases. In addition to the requirement to disable Option 114 in order to prevent the captive portal URL being used in network detection on the Production network, IOS 16.0, unlinke 15.1 does not immediately take a new lease on the Production network following the interface re-connect and NACK from the new DHCP server. It hangs out until the lease is expired from the Registration network. Diego, who helped a lot by suggesting we try not using Option 114 on the Registration VLAN, had asked about the fact that we saw delayed re-DHCPing when switching to our Production VLAN. Since the iPhone with IOS 15.1 we started to exclusively test with was not reproducing this behaviour, we simply chalked it up to more aggressive dnsmasq options we had deployed during an upgrade of the gateway platform, that among other things, shortened the DHCP handshake from 4 messages to 2 messages. option rapidcommit '1' option force '1' As it turns out, it is IOS 16 that caused this behavior. To wrap up our QA testing today we tested this newer IOS platform, and sure enough, right away noticed this not re-DHCPing behaviour on the production network. Rather than shorten our Registration VLAN lease time to encourage a quicker switch (which can cause a refresh of the portal registration / Apple Log In page during email entry) we resolved this by extending the network redirect delay. In our case, 70 seconds is long enough, which is longer than the Registration VLAN lease time (30s) plus our fencing delay of 20s, plus a small buffer, to ensure the new iPhones have enough time to perform network detection on the Production network before the portal network evaluation progress bar expires. All this is only necessary if your portal listener is available publically in a non-inline Captive Portal topology, as without access to the portal listener on the production network, the iphone devices determine the network is available when they can no longer reach the portal URL passed in Option 114 from the Registration VLAN. cheers, Ian On Thu, Jan 26, 2023 at 7:13 PM Ian MacDonald <im...@ne...> wrote: > Diego, > > Thanks for your additional input. As it turns out, DHCP option 114 on > the Registration network is creating the problem for recent iPhones. The > bulk of my testing has been with an iPhone 7 Pro running IOS 15.1, but I > believe this device behaves similarly to an iPhone 12 Pro uptodate on IOS > 16. > > As learned from https://github.com/inverse-inc/packetfence/issues/5638, > the Option 114 is only advertised on the Registration network when the > portal has a valid SSL certificate, and secure-redirect is enabled. There > is a important catch, which cost me a lot of misunderstood test cycles. > You can not just make a change to the Secure-Redirect option and restart > the haproxy-portal and httpd.portal processes as prompted to when you > change the setting in the GUI. The dhcp server needs to be reconfigured. > The big learning point here is that I further discovered that disabling > and enabling the pfdhcp and pfdhcplistener services does not reconfigure > advertisement of Option 114. This lead me down a few testing wormholes > when I stumbled into working scenarios after changing other options in > conjunction with secure-redirect AND executed a full CLI pf service > restart. > > Starting today, to impact the Option 114 advertisement, I have now been > using a full /usr/local/pf/bin/pfcmd service pf stop followed by /usr/local/pf/bin/pfcmd > service pf start > > With secure-redirect enabled, I have found no way to get the iPhones to > perform network detection properly. This included variations of short and > long network_detection_initial_delay, and network_redirect_delay toggling > of portal_csp_security_headers as well as using a variety of Option 114 > values on the Production network server, including no value, the RFC > defined urn:ietf:params:capport:unrestricted and a test api provided by > Diego emulating a passthrough response. > > After reading about other struggles with Option 114 in the Apple developer > network forums: https://developer.apple.com/forums/thread/660827 it > appears that the implementation does an API evaluation on subsequent > connection attempts, as described on the phone as > > Attempt 1: com.apple.captive default 12:04:40.051877+0300 configd en0: > Probing 'portal2' > Attempt 2: com.apple.captive default 12:08:19.191328+0300 configd en0: > Evaluating API 'portal2' > > If the switch from Registration (attempt 1) to Default Network (attempt 2) > is consistent with this, it explains why having the Option 114 present is > causing the iPhone to use it again, for the same SSID, on the Production > network one the VLAN switch has occurred. > > Earlier versions of packetfence may be working around this, as the Option > 114 was only introduced at 10.2.0. > > On 12.1, disabling secure-redirect/Option 114, seems to provide a > workaround for the iPhones. It seems that it is working on our 11.0 as > well once we have fully restarted services with secure-redirect disabled, > something we had missed by limiting our changes to the GUI restarting > process in production. > > Our current workaround, in order to have Secure-Redirect enabled, which > seems like a more forward compatible configuration, and have Option 114 > disabled, is starting the Packetfence server with Secure-Redirect > disabled, and then enabling it in the GUI and restarting portal processes, > which leaves the DHCP services configured without Option 114. This seems > to be working in PF 12.1 and PF11.0 for us. > > We are considering to then disable secure-redirect via CLI, once in the > workaround scenario, to avoid any sort of iPhone issues on an unplanned > restart that would add back Option 114, but we have not tested the > configuration tracking well enough to confidently do this. > > I created a request to allow for configuration of Secure-Redirect without > Option114 to allow an easier way to get iPhones and Secure-Redirect working > with the Captive Portal. > https://github.com/inverse-inc/packetfence/issues/7478 > > cheers, > Ian > > > On Wed, Jan 25, 2023 at 5:59 PM Diego Garcia del Rio <ga...@gm...> > wrote: > >> Hi Ian >> >> I do have DHCP option 114 on the registration / isolation networks. >> >> I am using all the default timings (I have different setups, ranging from >> PF 7.0 till 11.0). I am not yet using PF 12 with containers. >> >> I haven't checked specifically for the network detection... (I havent >> looked at the mechanism) but it has been working quite well so far. >> >> I will try to setup a test AP and see if I can do some testing. I Do have >> an iphone 12 at hand >> >> Cheers! >> >> >> On Wed, Jan 25, 2023 at 7:43 PM Ian MacDonald <im...@ne...> wrote: >> >>> On Wed, Jan 25, 2023 at 4:43 PM Diego Garcia del Rio <ga...@gm...> >>> wrote: >>> >>>> But yes.. I have around 25 networks with iphone users and so far >>>> they've been happy. With this being said, im in the southern hemisphere so >>>> its summer holidays right now. As such, I don't know if a very recent >>>> upgrade of IOS has broken things >>>> >>> >>> So not inline; no IPv6; no DHCP option 114. I do not think this is a >>> new IOS issue. It has been on my list for months to resolve, and I >>> expected 11.0-12.1 might have an impact. >>> >>> A couple of additional questions, >>> >>> Are you able to share your captive portal timing settings? >>> Have you seen the iPhone do network detection using the IP/image passed >>> in the current javascript implementation in a capture? >>> >>> cheers, >>> Ian >>> >>> >>>> On Wed, Jan 25, 2023 at 6:08 PM Ian MacDonald <im...@ne...> >>>> wrote: >>>> >>>>> Diego, >>>>> >>>>> That is insightful. iPhones can work (I was waiting for somebody to >>>>> confirm that) >>>>> >>>>> On your last idea, I was going to test without Option 114 on the >>>>> registration VLAN ; I read the comments from fdurand "set it as a >>>>> default option , only if the secure redirect option is enabled and the >>>>> certificate on the portal is valid. " >>>>> >>>>> I was going to test this tomorrow in the lab, having mangled the SSL >>>>> certs in addition to turning off secure-direct; We had secure-redirect off >>>>> in the packet capture test, so I think pfdhcp serves it up when it is >>>>> requested, as I saw it in our captures, but that sounds like different >>>>> behaviour than you saw back in your initial testing when you had to >>>>> forcibly restart pfdhcp to get it to serve it up [years ago]. I will >>>>> additionally check with the ssl broken to be sure of the behaviour. >>>>> >>>>> Tomorrow, I will also try your working URL+JSON, and a broken one too >>>>> (just a plain webserver) in our Default network dhcp. >>>>> >>>>> Some questions: >>>>> Is your iPhone happy environment topology routed? >>>>> Is your portal accessible from the Default network (i.e. the >>>>> Internet?) after capture release? >>>>> Do you have IPv6 enabled in Registration or Default? >>>>> >>>>> Ian >>>>> >>>>> >>>>> >>>>> >>>>> On Wed, Jan 25, 2023 at 12:55 PM Diego Garcia del Rio < >>>>> ga...@gm...> wrote: >>>>> >>>>>> Hi Ian >>>>>> >>>>>> Thanks for the detailed work and troubleshooting >>>>>> >>>>>> I wonder if what we're seeing is a recent change on apple's side. I >>>>>> manage several school's wifi systems with PF and we haven't seen this >>>>>> problem with the iphones. To be honest though, we were only serving the >>>>>> DHCP option 114 on the registration vlan and not on the production vlan >>>>>> once the user is registered. >>>>>> >>>>>> I have not had any experience with the dhcp option set to >>>>>> "urn:ietf:params:capport:unrestricted" which should tell the user to >>>>>> connect directly: (at least on android's source code I couldnt find any >>>>>> reference to that string) so im not sure its supported. It could easily be >>>>>> that apple has the same issue.. or worse, its trying to parse it wrongly... >>>>>> again, pure speculation. >>>>>> >>>>>> if you have a web server available somewhere.. maybe you could test >>>>>> serving a "static" json where the "device is connected" value is returned? >>>>>> >>>>>> can you try pointing the production dhcp server to this url? >>>>>> https://rfc8908.vercel.app/ >>>>>> >>>>>> (its a tiny server I just hosted which has the proper certificates >>>>>> and returns a "you're not on a portal" json). >>>>>> >>>>>> Maybe it helps? >>>>>> >>>>>> >>>>>> >>>>>> >>>>>> On Tue, Jan 24, 2023 at 1:28 PM Ian MacDonald via PacketFence-users < >>>>>> pac...@li...> wrote: >>>>>> >>>>>>> James, >>>>>>> >>>>>>> Thanks for the tips. >>>>>>> >>>>>>> We seemed to have isolated the issue to the iPhone using detection >>>>>>> of the captive portal URL as the network detection test. The simple >>>>>>> solution is to block the public facing Packetfence Portal IP on the Default >>>>>>> network, but that has the unintended consequence of blocking access to the >>>>>>> Packetfence activation link served up using the same hostname. >>>>>>> >>>>>>> Initially we got caught up in DHCP, and use of option 114, but the >>>>>>> phones are re-DHCPing properly. We learned a few things here I will >>>>>>> share, that I excluded from my recent post focusing on how to configure >>>>>>> packetfence to provide different hostnames for the captive portal vs email >>>>>>> activation in order to work with the iPhone captive portal mechanism. >>>>>>> >>>>>>> On DHCP, on the Default Network, we are using option rapidcommit '1' >>>>>>> which enables a 2-Message DHCP handshake, rather than a 4-Message DHCP >>>>>>> handshake per https://datatracker.ietf.org/doc/rfc4039/ This >>>>>>> greatly improves the speed and consistency of the clients on the Default >>>>>>> network. Noticeably the iPhone drops the Log In page capture as soon as it >>>>>>> lands on the Default network as expected. Prior to this tweak it seemed >>>>>>> to sometimes inconsistently sit on the Log In page evaluating the network; >>>>>>> Something that could perhaps be tuned a different way, but for us, we now >>>>>>> have quick, consistent, identical behaviour on the clients. This really >>>>>>> did point out to us, that it was re-detection of the Packetfence portal >>>>>>> page that popped the Log In screen back up, when all other indications and >>>>>>> traffic flows would be indicating that the device has Internet access. >>>>>>> >>>>>>> The other thing we learned about DHCP, is that setting the >>>>>>> Registration DHCP server to 15s from 30s would cause the Log In page to >>>>>>> disappear and reappear when the lease was being renewed. With the 15s >>>>>>> period, it really increased the liklihood that this would happen on the Log >>>>>>> In page, while the user was entering their email. Basically as you were >>>>>>> entering the email, the client would close and open the Log In page as the >>>>>>> lease renewed, forcing the user to start again entering the email address. >>>>>>> This was a bit annoying, so we have relaxed it back to 30s, as that was the >>>>>>> only perceived impact it had on the flow with the iPhone, and it was a >>>>>>> negative impact. >>>>>>> >>>>>>> It did point out to us that the iPhone does re-load its captive >>>>>>> portal mechanism cleanly with DHCP, yet on the Default network it ignores >>>>>>> our option 114, and persists the Log In page URL it learned from the >>>>>>> Packetfence API/DHCP. >>>>>>> >>>>>>> All to say, we are really now just focused on properly handling the >>>>>>> detection. It is a configuration exercise that we are looking to figure >>>>>>> out that would have us do one of the following: >>>>>>> 1) Change the Captive Portal configuration to tell the iPhone to >>>>>>> behave differently via the detection mechanism URL and API - nothing we can >>>>>>> see in the GUI or configs provides an obvious path forwards here, it looks >>>>>>> like the iPhone isn't executing the detectNetworkAccess script in the >>>>>>> intended way >>>>>>> 2) Modify the configuration of the Packetfence network or portal >>>>>>> server to separate the requests to the captive portal and email activation >>>>>>> by hostname so that one could be blackholed on the Default Network easily >>>>>>> using DNS >>>>>>> >>>>>>> A final option, if we can not do either of these in packetfence, >>>>>>> 3) is to stand-up an ALG of some kind in front of the public >>>>>>> packetfence portal listener that filters out the requests not to the email >>>>>>> activation URLs from the Default network; This seems like a lot of work >>>>>>> for something that we expect should be configurable somehow >>>>>>> >>>>>>> We tried the variation of turning off secure-redirect, hoping that >>>>>>> the Portal Server detection would stick to 80, and we know the activation >>>>>>> link would always be port 443, but this did not work. The iPhone tries >>>>>>> https even with secure-redirect off. >>>>>>> >>>>>>> And if we know that 1) or 2) are not possible, but in the roadmap >>>>>>> Packetfence, or a change is coming to fix the iPhone handling in >>>>>>> javascript, we would just post something on the Log In page during network >>>>>>> evaluation to guide iPhone users through the "Use Without Internet" option >>>>>>> for now, with a link to a layman term explanation of our expectation that >>>>>>> we can fix this. >>>>>>> >>>>>>> What I do not really understand is how inline configurations avoid >>>>>>> this issue, or are we one of a very few entities using Packetfence to >>>>>>> directly interact with iPhones for captive portal, and this scenario is >>>>>>> known to anyone using Packetfence for captive portal directly with iPhone >>>>>>> in any sort of network topology that does not have another controller >>>>>>> handling the actual captive portal interaction. >>>>>>> >>>>>>> Apples handling of the Captive Portal is described here: >>>>>>> https://developer.apple.com/news/?id=q78sq5rv >>>>>>> And maybe it isn't using the DHCP options properly as noted here: >>>>>>> https://developer.apple.com/forums/thread/712120 >>>>>>> >>>>>>> I'm not sure getting Apple to change anything is really a viable >>>>>>> option. We do not see any frames with Content-Type: >>>>>>> application/captive+json in our portal interactions, so I think we are >>>>>>> relying on a more basic mechanism where a JS script is executing on the Log >>>>>>> In page. There is a text/javascript detectNetworkAccess(vars.retry_delay, >>>>>>> vars_destination_url, vars.external_ip, vars.image_page) being >>>>>>> passed after a text/html that has all the variables defined as in our >>>>>>> configuration, but setting them to a wide range of values has no impact - >>>>>>> the iPhone comes back to the captive portal URL, not the destination_url >>>>>>> or the external_ip+image_path in order to do its detection. >>>>>>> >>>>>>> cheers, >>>>>>> Ian >>>>>>> >>>>>>> >>>>>>> >>>>>>> On Tue, Jan 24, 2023 at 6:17 AM James Andrewartha via >>>>>>> PacketFence-users <pac...@li...> wrote: >>>>>>> >>>>>>>> Hi Ian, >>>>>>>> >>>>>>>> It's a curious problem alright. I don't have any solutions, but >>>>>>>> https://www.numerousnetworks.co.uk/noversight/ might be able to >>>>>>>> give you >>>>>>>> some more information, it will pull the iPhone's wifi logs and >>>>>>>> analyse them. >>>>>>>> >>>>>>>> There's also the wifi debug profile, you'll need an apple developer >>>>>>>> account to download it >>>>>>>> >>>>>>>> https://developer.apple.com/services-account/download?path=/iOS/iOS_Logs/MegaWifiProfile.mobileconfig >>>>>>>> >>>>>>>> For iOS 16, there's some discussion that claims it's using a public >>>>>>>> DNS >>>>>>>> request for the captive portal, although that would be unrelated to >>>>>>>> your >>>>>>>> experience of the phone not re-DHCPing after disconnect. >>>>>>>> >>>>>>>> https://community.arubanetworks.com/discussion/iphone-cannot-authanticate-with-captive-portal >>>>>>>> Thanks, >>>>>>>> >>>>>>>> -- >>>>>>>> James Andrewartha >>>>>>>> Network & Projects Engineer >>>>>>>> Christ Church Grammar School >>>>>>>> Claremont, Western Australia >>>>>>>> Ph. (08) 9442 1757 >>>>>>>> Mob. 0424 160 877 >>>>>>>> >>>>>>>> On 19/1/23 13:37, Ian MacDonald via PacketFence-users wrote: >>>>>>>> > Well, >>>>>>>> > >>>>>>>> > I guess we are stuck without more insight on how to get the >>>>>>>> iPhone to >>>>>>>> > update it's IP after the WiFi disconnect/reconnect to the Default >>>>>>>> VLAN. >>>>>>>> > >>>>>>>> > The only scenario I can think of, is that the iPhone believes it >>>>>>>> is on >>>>>>>> > the same network, and behaves like it is moving between >>>>>>>> different >>>>>>>> > ESSIDs on a mesh network which would not initiate a DHCP request; >>>>>>>> which >>>>>>>> > isn't the case here. >>>>>>>> > >>>>>>>> > I wonder if we plugged the iPhone into a USB dongle and tried the >>>>>>>> same >>>>>>>> > thing on a wired connection, if it would behave the same way.I'm >>>>>>>> not >>>>>>>> > going to test this as it doesn't solve anything. >>>>>>>> > >>>>>>>> > Ideas >>>>>>>> > >>>>>>>> > - shorten registration DHCP to inside the captive portal delay >>>>>>>> seems >>>>>>>> > like a good option to try >>>>>>>> > - I am wondering if there is any way I can get our DHCP server to >>>>>>>> > respond to the request we saw from the iPhone on the old >>>>>>>> registration >>>>>>>> > VLAN .. that may have actually been due to the lease expiring; at >>>>>>>> 30s as >>>>>>>> > you suggested it may be configured. Hopefully expiring at 10s >>>>>>>> before the >>>>>>>> > disconnect creates a DISCOVER rather than request for refresh on >>>>>>>> old >>>>>>>> > registration VLAN subnet to a DHCP server that is unreachable >>>>>>>> > - I am wondering if there is any signal PF can send after >>>>>>>> registration >>>>>>>> > via captive portal URL to help - like tell it to behave like an >>>>>>>> old device >>>>>>>> > - I am thinking maybe including a forced redirect URL in the >>>>>>>> connection >>>>>>>> > profile might help the trigger - I don't quite understand how it >>>>>>>> is >>>>>>>> > passed, but must be from the portal server URL to exist after the >>>>>>>> VLAN >>>>>>>> > switch >>>>>>>> > - double check there are no authoritative setting for DHCP on my >>>>>>>> Default >>>>>>>> > network that would allow it to signal to the iPhone when it sees >>>>>>>> any >>>>>>>> > DHCP traffic, like the frame you saw requesting a URL. >>>>>>>> > - is there a wifi feature we can turn off at a lower layer that >>>>>>>> would >>>>>>>> > ensure all wifi disconnects are treated like an interface up/down >>>>>>>> - like >>>>>>>> > disabling roaming features on the AP >>>>>>>> > >>>>>>>> > Maybe the PF team are aware of this scenario; it would be nice to >>>>>>>> know >>>>>>>> > we are near the end of the road. >>>>>>>> > >>>>>>>> > Any help appreciated >>>>>>>> > >>>>>>>> > Cheers, >>>>>>>> > Ian >>>>>>>> > >>>>>>>> > >>>>>>>> > On Wed., Jan. 18, 2023, 10:57 p.m. Diego Garcia del Rio, >>>>>>>> > <ga...@gm... <mailto:ga...@gm...>> wrote: >>>>>>>> > >>>>>>>> > Hi Ian >>>>>>>> > >>>>>>>> > thanks for the extremely thorough troubleshooting. >>>>>>>> > >>>>>>>> > Its very weird that the client is not requesting dhcp after >>>>>>>> > re-connecting. On the AP side, it seems like its >>>>>>>> disconnecting the >>>>>>>> > client, so im surprised its not doing a new DHCP request, >>>>>>>> > >>>>>>>> > An option you might have is to change the dhcp lease time of >>>>>>>> the >>>>>>>> > registration server. By default, its setup for 30 seconds, >>>>>>>> but it >>>>>>>> > _might_ be editable.. I would try setting it for maybe 10 >>>>>>>> seconds? >>>>>>>> > >>>>>>>> > the client is requesting the dhcp option 114 (you can see the >>>>>>>> > mention to "URL" in the dhcp capture below) >>>>>>>> > Parameter-Request Option 55, length 9: >>>>>>>> > Subnet-Mask, Classless-Static-Route, Default-Gateway, >>>>>>>> > Domain-Name-Server >>>>>>>> > Domain-Name, Option 108, *URL*, Option 119 >>>>>>>> > Option 252 >>>>>>>> > >>>>>>>> > >>>>>>>> > And your reply is correct... (with the urn saying no >>>>>>>> > portal/unrestricted) >>>>>>>> > >>>>>>>> > also, regarding iphone 7..it can go up to IOS15, and the >>>>>>>> captive >>>>>>>> > portal url via dhcp was added in IOS14, so the fact it >>>>>>>> matches newer >>>>>>>> > iphones is not as strange... >>>>>>>> > >>>>>>>> > Unfortunately, I dont think PF can issue dhcp disconnects >>>>>>>> (and most >>>>>>>> > clients ignore it). (It would actually be a "FORCERENEW" >>>>>>>> message >>>>>>>> > from the server, but it would still be a race condition >>>>>>>> against the >>>>>>>> > radius disconnect) >>>>>>>> > >>>>>>>> > >>>>>>>> > >>>>>>>> > >>>>>>>> > >>>>>>>> > >>>>>>>> > >>>>>>>> > On Thu, Jan 19, 2023 at 3:27 AM Ian MacDonald via >>>>>>>> PacketFence-users >>>>>>>> > <pac...@li... >>>>>>>> > <mailto:pac...@li...>> wrote: >>>>>>>> > >>>>>>>> > Hello PF, >>>>>>>> > >>>>>>>> > I have started a new thread after posting to "Newer Model >>>>>>>> > iPhones and Android Devices showing MAC:0 in Captive >>>>>>>> Portal" as >>>>>>>> > the problem we are having seems to be different then we >>>>>>>> > initially described, and we have modified our >>>>>>>> configuration to >>>>>>>> > resolve some related potential issues along the way. >>>>>>>> Thanks >>>>>>>> > Diego for some insights that helped us narrow our problem >>>>>>>> scope >>>>>>>> > and eliminate a few potential other causes. >>>>>>>> > >>>>>>>> > Our narrowed down problem scope seems to be that some >>>>>>>> devices >>>>>>>> > (iPhone 7, iPhone 12 Pro) are not are not properly >>>>>>>> requesting a >>>>>>>> > new DHCP lease on the Default network after they have >>>>>>>> been WiFi >>>>>>>> > disconnected from the Registration VLAN and reconnected >>>>>>>> to the >>>>>>>> > Default VLAN. Details follow as well as some logs from a >>>>>>>> recent >>>>>>>> > capture of an iPhone 12 Pro. We see identical behaviour >>>>>>>> on >>>>>>>> > iPhone 7. This issue does not seem to impact the iPhone >>>>>>>> 5s and >>>>>>>> > Samsung Galaxy S10. >>>>>>>> > >>>>>>>> > We are wondering if there is more PF can do on the >>>>>>>> Registration >>>>>>>> > VLAN, like a DHCP Release to help clients be ready when >>>>>>>> they >>>>>>>> > arrive on the Default VLAN. >>>>>>>> > >>>>>>>> > Our PF setup in the lab where we are having issues is >>>>>>>> described >>>>>>>> > in the diagram below >>>>>>>> > image.png >>>>>>>> > [fencing] >>>>>>>> > wait_for_redirect = 25 >>>>>>>> > [captive_portal] >>>>>>>> > network_redirect_delay=35s >>>>>>>> > [interface eth0] >>>>>>>> > type=management,portal >>>>>>>> > mask=255.255.255.0 >>>>>>>> > ip=10.2.1.2 >>>>>>>> > [interface eth1] >>>>>>>> > type=internal >>>>>>>> > mask=255.255.255.0 >>>>>>>> > ip=10.2.2.2 >>>>>>>> > enforcement=vlan >>>>>>>> > [interface eth2] >>>>>>>> > enforcement=vlan >>>>>>>> > ip=10.2.3.2 >>>>>>>> > mask=255.255.255.0 >>>>>>>> > type=internal >>>>>>>> > >>>>>>>> > The process starts with an Unregistered node, and no >>>>>>>> remembered >>>>>>>> > local wifi networks on the iPhone 12 Pro. The events >>>>>>>> happen as >>>>>>>> > follows: >>>>>>>> > >>>>>>>> > First we connect the PF4_Office:TestOne_WiFi SSID where >>>>>>>> the >>>>>>>> > device connects to VLAN 81 and is presented the >>>>>>>> Registration >>>>>>>> > portal page with AUP and a prompt for email based >>>>>>>> authentication. >>>>>>>> > On the NAS/AP we see the established connection: >>>>>>>> > >>>>>>>> > Wed Jan 18 *14:54:55 *2023 daemon.info < >>>>>>>> http://daemon.info> >>>>>>>> > hostapd: wlan0: STA f2:ef:bb:22:8c:62 *RADIUS: VLAN ID 81* >>>>>>>> > Wed Jan 18 14:54:55 2023 daemon.info <http://daemon.info> >>>>>>>> > hostapd: wlan0: STA f2:ef:bb:22:8c:62 IEEE 802.11: >>>>>>>> authenticated >>>>>>>> > Wed Jan 18 14:54:55 2023 daemon.info <http://daemon.info> >>>>>>>> > hostapd: wlan0: STA f2:ef:bb:22:8c:62 IEEE 802.11: >>>>>>>> associated >>>>>>>> > (aid 2) >>>>>>>> > Wed Jan 18 *14:54:55* 2023 daemon.notice hostapd: wlan0: >>>>>>>> > *AP-STA-CONNECTED f2:ef:bb:22:8c:62* >>>>>>>> > Wed Jan 18 14:54:55 2023 daemon.info <http://daemon.info> >>>>>>>> > hostapd: wlan0: STA f2:ef:bb:22:8c:62 RADIUS: starting >>>>>>>> > accounting session 2DB2C59D34BD1998 >>>>>>>> > >>>>>>>> > And on our management network the matching authorized >>>>>>>> RADIUS >>>>>>>> > messages between the NAS/AP and PF server on our >>>>>>>> management network >>>>>>>> > 14:54:55.204084 IP 10.2.1.11.49421 > 10.2.1.2.1812: >>>>>>>> RADIUS, >>>>>>>> > Access-Request (1), id: 0x1c length: 164 >>>>>>>> > 14:54:55.251883 IP 10.2.1.2.1812 > 10.2.1.11.49421: >>>>>>>> RADIUS, >>>>>>>> > Access-Accept (2), id: 0x1c length: 36 >>>>>>>> > 14:54:55.261410 IP 10.2.1.11.48577 > 10.2.1.2.1813: >>>>>>>> RADIUS, >>>>>>>> > Accounting-Request (4), id: 0x1d length: 182 >>>>>>>> > 14:54:55.263588 IP 10.2.1.2.1813 > 10.2.1.11.48577: >>>>>>>> RADIUS, >>>>>>>> > Accounting-Response (5), id: 0x1d length: 35 >>>>>>>> > >>>>>>>> > In our packetfence logs we see the client connect to to >>>>>>>> the >>>>>>>> > registration vlan 81 and match our connection profile by >>>>>>>> ssid >>>>>>>> > TestOne_WiFi >>>>>>>> > Jan 18 14:54:55 pf4 httpd.aaa-docker-wrapper[2299]: >>>>>>>> httpd.aaa(7) >>>>>>>> > INFO: [mac:f2:ef:bb:22:8c:62] handling radius autz >>>>>>>> request: from >>>>>>>> > switch_ip => (10.2.1.11), connection_type => >>>>>>>> > Wireless-802.11-NoEAP,switch_mac => (ec:08:6b:6a:63:5a), >>>>>>>> mac => >>>>>>>> > [f2:ef:bb:22:8c:62], port => 0, username => >>>>>>>> "f2efbb228c62", ssid >>>>>>>> > => TestOne_WiFi (pf::radius::authorize) >>>>>>>> > Jan 18 14:54:55 pf4 httpd.aaa-docker-wrapper[2299]: >>>>>>>> httpd.aaa(7) >>>>>>>> > INFO: [mac:f2:ef:bb:22:8c:62] Instantiate profile >>>>>>>> Test_WiFi >>>>>>>> > (pf::Connection::ProfileFactory::_from_profile) >>>>>>>> > Jan 18 14:54:55 pf4 httpd.aaa-docker-wrapper[2299]: >>>>>>>> httpd.aaa(7) >>>>>>>> > INFO: [mac:f2:ef:bb:22:8c:62] is of status unreg; belongs >>>>>>>> into >>>>>>>> > registration VLAN (pf::role::getRegistrationRole) >>>>>>>> > Jan 18 *14:54:55* pf4 httpd.aaa-docker-wrapper[2299]: >>>>>>>> > httpd.aaa(7) INFO: [mac:f2:ef:bb:22:8c:62] *(10.2.1.11) >>>>>>>> Added >>>>>>>> > VLAN 81 to the returned RADIUS Access-Accept* >>>>>>>> > (pf::Switch::returnRadiusAccessAccept) >>>>>>>> > Jan 18 14:54:55 pf4 httpd.aaa-docker-wrapper[2299]: >>>>>>>> httpd.aaa(7) >>>>>>>> > INFO: [mac:f2:ef:bb:22:8c:62] Updating locationlog from >>>>>>>> > accounting request (pf::api::handle_accounting_metadata) >>>>>>>> > Jan 18 14:54:59 pf4 pfqueue[64840]: pfqueue(64840) INFO: >>>>>>>> > [mac:f2:ef:bb:22:8c:62] Sending a firewall SSO 'Update' >>>>>>>> request >>>>>>>> > for MAC 'f2:ef:bb:22:8c:62' and IP '10.2.2.178' >>>>>>>> > (pf::firewallsso::do_sso) >>>>>>>> > Jan 18 14:54:59 pf4 pfqueue[64840]: pfqueue(64840) WARN: >>>>>>>> > [mac:f2:ef:bb:22:8c:62] Unable to match MAC address to IP >>>>>>>> > '10.2.2.178' (pf::ip4log::ip2mac) >>>>>>>> > Jan 18 14:54:59 pf4 pfqueue[65681]: pfqueue(65681) INFO: >>>>>>>> > [mac:f2:ef:bb:22:8c:62] Instantiate profile Test_WiFi >>>>>>>> > (pf::Connection::ProfileFactory::_from_profile) >>>>>>>> > Jan 18 14:54:59 pf4 pfqueue[64476]: pfqueue(64476) WARN: >>>>>>>> > [mac:f2:ef:bb:22:8c:62] Unable to pull accounting history >>>>>>>> for >>>>>>>> > device f2:ef:bb:22:8c:62. The history set doesn't exist >>>>>>>> yet. >>>>>>>> > (pf::accounting_events_history::latest_mac_history) >>>>>>>> > Jan 18 14:54:59 pf4 pfqueue[64476]: pfqueue(64476) WARN: >>>>>>>> > [mac:f2:ef:bb:22:8c:62] Unable to pull accounting history >>>>>>>> for >>>>>>>> > device f2:ef:bb:22:8c:62. The history set doesn't exist >>>>>>>> yet. >>>>>>>> > (pf::accounting_events_history::latest_mac_history) >>>>>>>> > Jan 18 14:55:01 pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(94) INFO: [mac:f2:ef:bb:22:8c:62] Instantiate >>>>>>>> > profile Test_WiFi >>>>>>>> (pf::Connection::ProfileFactory::_from_profile) >>>>>>>> > Jan 18 14:55:02 pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(96) INFO: [mac:f2:ef:bb:22:8c:62] Instantiate >>>>>>>> > profile Test_WiFi >>>>>>>> (pf::Connection::ProfileFactory::_from_profile) >>>>>>>> > Jan 18 14:55:02 pf4 pfqueue[64520]: pfqueue(64520) WARN: >>>>>>>> > [mac:f2:ef:bb:22:8c:62] Unable to pull accounting history >>>>>>>> for >>>>>>>> > device f2:ef:bb:22:8c:62. The history set doesn't exist >>>>>>>> yet. >>>>>>>> > (pf::accounting_events_history::latest_mac_history) >>>>>>>> > Jan 18 14:55:02 pf4 pfqueue[64469]: pfqueue(64469) WARN: >>>>>>>> > [mac:f2:ef:bb:22:8c:62] Unable to pull accounting history >>>>>>>> for >>>>>>>> > device f2:ef:bb:22:8c:62. The history set doesn't exist >>>>>>>> yet. >>>>>>>> > (pf::accounting_events_history::latest_mac_history) >>>>>>>> > Jan 18 14:55:09 pf4 pfperl-api-docker-wrapper[1130]: >>>>>>>> > pfperl-api(17) INFO: [mac:[undef]] Using 300 resolution >>>>>>>> > threshold (pf::pfcron::task::cluster_check::run) >>>>>>>> > Jan 18 14:55:09 pf4 pfperl-api-docker-wrapper[1130]: >>>>>>>> > pfperl-api(17) INFO: [mac:[undef]] All cluster members are >>>>>>>> > running the same configuration version >>>>>>>> > (pf::pfcron::task::cluster_check::run) >>>>>>>> > Jan 18 14:55:10 pf4 pfperl-api-docker-wrapper[1130]: >>>>>>>> > pfperl-api(17) INFO: [mac:[undef]] processed 0 >>>>>>>> security_events >>>>>>>> > during security_event maintenance (1674071710.15351 >>>>>>>> > 1674071710.16509) >>>>>>>> (pf::security_event::security_event_maintenance) >>>>>>>> > Jan 18 14:55:10 pf4 pfperl-api-docker-wrapper[1130]: >>>>>>>> > pfperl-api(17) INFO: [mac:[undef]] getting security_events >>>>>>>> > triggers for accounting cleanup >>>>>>>> (pf::accounting::acct_maintenance) >>>>>>>> > Jan 18 14:55:12 pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(96) INFO: [mac:f2:ef:bb:22:8c:62] Instantiate >>>>>>>> > profile Test_WiFi >>>>>>>> (pf::Connection::ProfileFactory::_from_profile) >>>>>>>> > Jan 18 14:55:12 pf4 pfqueue[64520]: pfqueue(64520) WARN: >>>>>>>> > [mac:f2:ef:bb:22:8c:62] Unable to pull accounting history >>>>>>>> for >>>>>>>> > device f2:ef:bb:22:8c:62. The history set doesn't exist >>>>>>>> yet. >>>>>>>> > (pf::accounting_events_history::latest_mac_history) >>>>>>>> > >>>>>>>> > We can see the Registration VLAN portal interactions for >>>>>>>> the >>>>>>>> > client on 10.2.2.178 >>>>>>>> > Jan 18 14:55:00 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:54627 <http://10.2.2.178:54627> >>>>>>>> > [18/Jan/2023:14:55:00.140] portal-http-10.2.1.2 >>>>>>>> proxy/proxy >>>>>>>> > 0/0/0/452/452 200 644 - - ---- 2/1/0/0/0 0/0 { >>>>>>>> captive.apple.com >>>>>>>> > <http://captive.apple.com>} "GET /hotspot-detect.html >>>>>>>> HTTP/1.0" >>>>>>>> > Jan 18 14:55:01 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62360 <http://10.2.2.178:62360> >>>>>>>> > [18/Jan/2023:14:55:01.513] portal-http-10.2.1.2 >>>>>>>> proxy/proxy >>>>>>>> > 0/0/1/5/6 200 644 - - ---- 2/1/0/0/0 0/0 { >>>>>>>> captive.apple.com >>>>>>>> > <http://captive.apple.com>} "GET /hotspot-detect.html >>>>>>>> HTTP/1.1" >>>>>>>> > Jan 18 14:55:01 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:54632 <http://10.2.2.178:54632> >>>>>>>> > [18/Jan/2023:14:55:01.538] portal-http-10.2.1.2 >>>>>>>> proxy/proxy >>>>>>>> > 0/0/0/4/4 200 644 - - ---- 3/2/0/0/0 0/0 { >>>>>>>> captive.apple.com >>>>>>>> > <http://captive.apple.com>} "GET /hotspot-detect.html >>>>>>>> HTTP/1.0" >>>>>>>> > Jan 18 14:55:01 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62361 <http://10.2.2.178:62361> >>>>>>>> > [18/Jan/2023:14:55:01.762] portal-https-10.2.1.2~ >>>>>>>> > 10.2.1.2-backend/containers-gateway.internal:8080 >>>>>>>> 0/0/1/138/139 >>>>>>>> > 200 6858 - - ---- 3/1/0/0/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "GET >>>>>>>> > /captive-portal?destination_url= >>>>>>>> http://captive.apple.com/hotspot-detect.html < >>>>>>>> http://captive.apple.com/hotspot-detect.html> HTTP/1.1" >>>>>>>> > Jan 18 14:55:01 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62361 <http://10.2.2.178:62361> >>>>>>>> > [18/Jan/2023:14:55:01.930] portal-https-10.2.1.2~ >>>>>>>> static/static >>>>>>>> > 0/0/0/1/1 200 42006 - - ---- 4/1/0/0/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "GET /common/styles.css HTTP/1.1" >>>>>>>> > Jan 18 14:55:02 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62364 <http://10.2.2.178:62364> >>>>>>>> > [18/Jan/2023:14:55:02.003] portal-https-10.2.1.2~ >>>>>>>> static/static >>>>>>>> > 0/0/0/1/2 200 20248 - - ---- 8/5/0/0/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "GET /common/qrcode.min.js >>>>>>>> HTTP/1.1" >>>>>>>> > Jan 18 14:55:02 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62365 <http://10.2.2.178:62365> >>>>>>>> > [18/Jan/2023:14:55:02.016] portal-https-10.2.1.2~ >>>>>>>> static/static >>>>>>>> > 0/0/1/1/2 200 1506 - - ---- 8/5/0/0/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "GET /common/jquery-shim.js >>>>>>>> HTTP/1.1" >>>>>>>> > Jan 18 14:55:02 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62362 <http://10.2.2.178:62362> >>>>>>>> > [18/Jan/2023:14:55:02.019] portal-https-10.2.1.2~ >>>>>>>> static/static >>>>>>>> > 0/0/0/1/1 200 6157 - - ---- 8/5/1/1/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "GET /common/pf.js HTTP/1.1" >>>>>>>> > Jan 18 14:55:02 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62363 <http://10.2.2.178:62363> >>>>>>>> > [18/Jan/2023:14:55:02.019] portal-https-10.2.1.2~ >>>>>>>> static/static >>>>>>>> > 0/0/0/2/2 200 8239 - - ---- 8/5/0/0/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "GET /content/captiveportal.js >>>>>>>> HTTP/1.1" >>>>>>>> > Jan 18 14:55:02 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62361 <http://10.2.2.178:62361> >>>>>>>> > [18/Jan/2023:14:55:02.027] portal-https-10.2.1.2~ >>>>>>>> static/static >>>>>>>> > 0/0/0/1/1 200 4480 - - ---- 8/5/0/0/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "GET /common/packetfence-cp.png >>>>>>>> HTTP/1.1" >>>>>>>> > Jan 18 14:55:02 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62365 <http://10.2.2.178:62365> >>>>>>>> > [18/Jan/2023:14:55:02.033] portal-https-10.2.1.2~ >>>>>>>> static/static >>>>>>>> > 0/0/0/2/2 200 39912 - - ---- 8/5/0/0/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "GET /common/img/sprite.svg >>>>>>>> HTTP/1.1" >>>>>>>> > Jan 18 14:55:02 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62364 <http://10.2.2.178:62364> >>>>>>>> > [18/Jan/2023:14:55:02.032] portal-https-10.2.1.2~ >>>>>>>> > 10.2.1.2-backend/containers-gateway.internal:8080 >>>>>>>> 0/0/0/58/58 >>>>>>>> > 200 852 - - ---- 8/5/0/0/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "POST /record_destination_url >>>>>>>> HTTP/1.1" >>>>>>>> > Jan 18 14:55:04 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:54633 <http://10.2.2.178:54633> >>>>>>>> > [18/Jan/2023:14:55:01.930] portal-http-10.2.1.2 >>>>>>>> proxy/proxy >>>>>>>> > 0/0/0/2671/2671 200 644 - - ---- 8/2/0/0/0 0/0 >>>>>>>> > {captive.apple.com <http://captive.apple.com>} "GET >>>>>>>> > /hotspot-detect.html HTTP/1.0" >>>>>>>> > >>>>>>>> > In our packetfence.log, the client sends the email >>>>>>>> address from >>>>>>>> > the Registration Portal page that appears on the iPhone >>>>>>>> and the >>>>>>>> > VLAN reevaluation is started >>>>>>>> > Jan 18 *14:55:13* pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(96) INFO: [mac:f2:ef:bb:22:8c:62] *User >>>>>>>> > en...@gm... <mailto:en...@gm...> has >>>>>>>> authenticated >>>>>>>> > on the portal.* >>>>>>>> > >>>>>>>> (captiveportal::PacketFence::DynamicRouting::Module::_username_set) >>>>>>>> > Jan 18 14:55:13 pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(96) INFO: [mac:f2:ef:bb:22:8c:62] new >>>>>>>> activation >>>>>>>> > code successfully generated (pf::activation::create) >>>>>>>> > Jan 18 14:55:13 pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(96) WARN: [mac:f2:ef:bb:22:8c:62] Calling >>>>>>>> match >>>>>>>> > with empty/invalid rule class. Defaulting to >>>>>>>> 'authentication' >>>>>>>> > (pf::authentication::match) >>>>>>>> > Jan 18 14:55:13 pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(96) INFO: [mac:f2:ef:bb:22:8c:62] Using >>>>>>>> sources >>>>>>>> > email for matching (pf::authentication::match) >>>>>>>> > Jan 18 14:55:13 pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(96) INFO: [mac:f2:ef:bb:22:8c:62] Matched >>>>>>>> rule >>>>>>>> > (catchall) in source email, returning actions. >>>>>>>> > (pf::Authentication::Source::match_rule) >>>>>>>> > Jan 18 14:55:13 pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(96) INFO: [mac:f2:ef:bb:22:8c:62] Matched >>>>>>>> rule >>>>>>>> > (catchall) in source email, returning actions. >>>>>>>> > (pf::Authentication::Source::match) >>>>>>>> > Jan 18 14:55:13 pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(96) INFO: [mac:f2:ef:bb:22:8c:62] Using >>>>>>>> sources >>>>>>>> > email for matching (pf::authentication::match) >>>>>>>> > Jan 18 14:55:13 pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(96) INFO: [mac:f2:ef:bb:22:8c:62] >>>>>>>> security_event >>>>>>>> > 1300003 force-closed for f2:ef:bb:22:8c:62 >>>>>>>> > (pf::security_event::security_event_force_close) >>>>>>>> > Jan 18 14:55:13 pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(96) INFO: [mac:f2:ef:bb:22:8c:62] Instantiate >>>>>>>> > profile Test_WiFi >>>>>>>> (pf::Connection::ProfileFactory::_from_profile) >>>>>>>> > Jan 18 14:55:13 pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(95) INFO: [mac:f2:ef:bb:22:8c:62] Instantiate >>>>>>>> > profile Test_WiFi >>>>>>>> (pf::Connection::ProfileFactory::_from_profile) >>>>>>>> > Jan 18 14:55:13 pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(95) WARN: [mac:f2:ef:bb:22:8c:62] locale >>>>>>>> from the >>>>>>>> > URL is not supported >>>>>>>> > >>>>>>>> (captiveportal::PacketFence::Controller::Root::getLanguages) >>>>>>>> > Jan 18 14:55:13 pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(95) INFO: [mac:f2:ef:bb:22:8c:62] Releasing >>>>>>>> device >>>>>>>> > >>>>>>>> (captiveportal::PacketFence::DynamicRouting::Module::Root::release) >>>>>>>> > Jan 18 14:55:13 pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(95) INFO: [mac:f2:ef:bb:22:8c:62] >>>>>>>> re-evaluating >>>>>>>> > access (manage_register called) >>>>>>>> (pf::enforcement::reevaluate_access) >>>>>>>> > Jan 18 14:55:13 pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(95) INFO: [mac:f2:ef:bb:22:8c:62] Instantiate >>>>>>>> > profile Test_WiFi >>>>>>>> (pf::Connection::ProfileFactory::_from_profile) >>>>>>>> > Jan 18 14:55:13 pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(95) INFO: [mac:f2:ef:bb:22:8c:62] VLAN >>>>>>>> reassignment >>>>>>>> > is forced. (pf::enforcement::_should_we_reassign_vlan) >>>>>>>> > Jan 18 14:55:13 pf4 httpd.portal-docker-wrapper[4460]: >>>>>>>> > httpd.portal(95) INFO: [mac:f2:ef:bb:22:8c:62] switch >>>>>>>> port is >>>>>>>> > (10.2.1.11) ifIndex 0connection type: WiFi MAC Auth >>>>>>>> > (pf::enforcement::_vlan_reevaluation) >>>>>>>> > Jan 18 14:55:13 pf4 pfqueue[64911]: pfqueue(64911) WARN: >>>>>>>> > [mac:f2:ef:bb:22:8c:62] Unable to pull accounting history >>>>>>>> for >>>>>>>> > device f2:ef:bb:22:8c:62. The history set doesn't exist >>>>>>>> yet. >>>>>>>> > (pf::accounting_events_history::latest_mac_history) >>>>>>>> > Jan 18 14:55:14 pf4 pfqueue[64476]: pfqueue(64476) INFO: >>>>>>>> > [mac:f2:ef:bb:22:8c:62] Sending a firewall SSO 'Update' >>>>>>>> request >>>>>>>> > for MAC 'f2:ef:bb:22:8c:62' and IP '10.2.2.178' >>>>>>>> > (pf::firewallsso::do_sso) >>>>>>>> > Jan 18 14:55:14 pf4 pfqueue[65697]: pfqueue(65697) INFO: >>>>>>>> > [mac:f2:ef:bb:22:8c:62] Instantiate profile Test_WiFi >>>>>>>> > (pf::Connection::ProfileFactory::_from_profile) >>>>>>>> > Jan 18 14:55:14 pf4 pfqueue[64469]: pfqueue(64469) WARN: >>>>>>>> > [mac:f2:ef:bb:22:8c:62] Unable to pull accounting history >>>>>>>> for >>>>>>>> > device f2:ef:bb:22:8c:62. The history set doesn't exist >>>>>>>> yet. >>>>>>>> > (pf::accounting_events_history::latest_mac_history) >>>>>>>> > >>>>>>>> > In the haproxy_portal.log we see some final activity on >>>>>>>> the >>>>>>>> > Registration portal waiting for the fencing delay to send >>>>>>>> the >>>>>>>> > Radius Disconnect. >>>>>>>> > >>>>>>>> > Jan 18 14:55:13 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62361 <http://10.2.2.178:62361> >>>>>>>> > [18/Jan/2023:14:55:12.224] portal-https-10.2.1.2~ >>>>>>>> > 10.2.1.2-backend/containers-gateway.internal:8080 >>>>>>>> > 0/0/0/1214/1214 302 1090 - - ---- 7/5/0/0/0 0/0 { >>>>>>>> pf4.test.com >>>>>>>> > <http://pf4.test.com>} "POST /signup HTTP/1.1" >>>>>>>> > Jan 18 14:55:13 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62366 <http://10.2.2.178:62366> >>>>>>>> > [18/Jan/2023:14:55:13.498] portal-http-10.2.1.2 >>>>>>>> > 10.2.1.2-backend/containers-gateway.internal:8080 >>>>>>>> 0/0/0/139/139 >>>>>>>> > 200 7800 - - ---- 8/2/0/0/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "GET /access?lang= HTTP/1.1" >>>>>>>> > Jan 18 14:55:13 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62366 <http://10.2.2.178:62366> >>>>>>>> > [18/Jan/2023:14:55:13.668] portal-http-10.2.1.2 >>>>>>>> static/static >>>>>>>> > 0/0/0/1/2 200 42006 - - ---- 9/3/0/0/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "GET /common/styles.css HTTP/1.1" >>>>>>>> > Jan 18 14:55:13 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62367 <http://10.2.2.178:62367> >>>>>>>> > [18/Jan/2023:14:55:13.677] portal-http-10.2.1.2 >>>>>>>> static/static >>>>>>>> > 0/0/0/3/3 200 6157 - - ---- 13/7/3/3/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "GET /common/pf.js HTTP/1.1" >>>>>>>> > Jan 18 14:55:13 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62369 <http://10.2.2.178:62369> >>>>>>>> > [18/Jan/2023:14:55:13.677] portal-http-10.2.1.2 >>>>>>>> static/static >>>>>>>> > 0/0/0/2/2 200 20248 - - ---- 13/7/2/2/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "GET /common/qrcode.min.js >>>>>>>> HTTP/1.1" >>>>>>>> > Jan 18 14:55:13 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62370 <http://10.2.2.178:62370> >>>>>>>> > [18/Jan/2023:14:55:13.677] portal-http-10.2.1.2 >>>>>>>> static/static >>>>>>>> > 0/0/0/3/3 200 1506 - - ---- 13/7/1/1/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "GET /common/jquery-shim.js >>>>>>>> HTTP/1.1" >>>>>>>> > Jan 18 14:55:13 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62368 <http://10.2.2.178:62368> >>>>>>>> > [18/Jan/2023:14:55:13.677] portal-http-10.2.1.2 >>>>>>>> static/static >>>>>>>> > 0/0/0/3/3 200 8239 - - ---- 13/7/0/0/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "GET /content/captiveportal.js >>>>>>>> HTTP/1.1" >>>>>>>> > Jan 18 14:55:13 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62366 <http://10.2.2.178:62366> >>>>>>>> > [18/Jan/2023:14:55:13.681] portal-http-10.2.1.2 >>>>>>>> static/static >>>>>>>> > 0/0/0/5/5 200 837 - - ---- 14/8/1/1/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "GET /content/timerbar.js >>>>>>>> HTTP/1.1" >>>>>>>> > Jan 18 14:55:13 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62371 <http://10.2.2.178:62371> >>>>>>>> > [18/Jan/2023:14:55:13.681] portal-http-10.2.1.2 >>>>>>>> static/static >>>>>>>> > 0/0/0/5/5 200 1640 - - ---- 14/8/0/0/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "GET /content/release.js HTTP/1.1" >>>>>>>> > Jan 18 14:55:13 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62366 <http://10.2.2.178:62366> >>>>>>>> > [18/Jan/2023:14:55:13.692] portal-http-10.2.1.2 >>>>>>>> static/static >>>>>>>> > 0/0/0/1/1 200 4480 - - ---- 14/8/0/0/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "GET /common/packetfence-cp.png >>>>>>>> HTTP/1.1" >>>>>>>> > Jan 18 14:55:13 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:62367 <http://10.2.2.178:62367> >>>>>>>> > [18/Jan/2023:14:55:13.697] portal-http-10.2.1.2 >>>>>>>> static/static >>>>>>>> > 0/0/0/1/1 200 39912 - - ---- 14/8/0/0/0 0/0 {pf4.test.com >>>>>>>> > <http://pf4.test.com>} "GET /common/img/sprite.svg >>>>>>>> HTTP/1.1" >>>>>>>> > Jan 18 14:55:16 pf4 haproxy-portal-docker-wrapper[1141]: >>>>>>>> > 10.2.2.178:54634 <http://10.2.2.178:54634> >>>>>>>> > [18/Jan/2023:14:55:13.663] portal-http-10.2.1.2 >>>>>>>> proxy/proxy >>>>>>>> > 0/0/1/2974/2975 200 644 - - ---- 14/8/0/0/0 0/0 >>>>>>>> > {captive.apple.com <http://captive.apple.com>} "GET >>>>>>>> > /hotspot-detect.html HTTP/1.0" >>>>>>>> > >>>>>>>> > In the packetfence.log after the fencing delay we see the >>>>>>>> > disconnect request >>>>>>>> > >>>>>>>> > Jan 18 14:55:28 pf4 pfqueue[65695]: pfqueue(65695) INFO: >>>>>>>> > [mac:f2:ef:bb:22:8c:62] [f2:ef:bb:22:8c:62] >>>>>>>> DesAssociating mac >>>>>>>> > on switch (10.2.1.11) (pf::api::desAssociate) >>>>>>>> > Jan 18 *14:55:28* pf4 pfqueue[65695]: pfqueue(65695) INFO: >>>>>>>> > [mac:f2:ef:bb:22:8c:62] *deauthenticating >>>>>>>> f2:ef:bb:22:8c:62 >>>>>>>> > (pf::Switch::Hostapd::radiusDisconnect)* >>>>>>>> > Jan 18 14:55:28 pf4 pfqueue[65695]: pfqueue(65695) INFO: >>>>>>>> > [mac:f2:ef:bb:22:8c:62] Will be using connnector >>>>>>>> local_connector >>>>>>>> > to perform the deauth >>>>>>>> (pf::Switch::radius_deauth_connection_info) >>>>>>>> > Jan 18 14:55:28 pf4 pfqueue[65695]: pfqueue(65695) WARN: >>>>>>>> > [mac:f2:ef:bb:22:8c:62] Warning: 1366: Incorrect string >>>>>>>> value: >>>>>>>> > '\xE3\xD1`=\x04\xC7...' for column >>>>>>>> > `pf`.`radius_audit_log`.`radius_reply` at row 1 >>>>>>>> > (pf::dal::db_execute) >>>>>>>> > Jan 18 14:55:28 pf4 httpd.aaa-docker-wrapper[2299]: >>>>>>>> httpd.aaa(7) >>>>>>>> > INFO: [mac:f2:ef:bb:22:8c:62] handling radius autz >>>>>>>> request: from >>>>>>>> > switch_ip => (10.2.1.11), connection_type => >>>>>>>> > Wireless-802.11-NoEAP,switch_mac => (ec:08:6b:6a:63:5a), >>>>>>>> mac => >>>>>>>> > [f2:ef:bb:22:8c:62], port => 0, username => >>>>>>>> "f2efbb228c62", ssid >>>>>>>> > => TestOne_WiFi (pf::radius::authorize) >>>>>>>> > Jan 18 14:55:28 pf4 httpd.aaa-docker-wrapper[2299]: >>>>>>>> httpd.aaa(7) >>>>>>>> > INFO: [mac:f2:ef:bb:22:8c:62] Instantiate profile >>>>>>>> Test_WiFi >>>>>>>> > (pf::Connection::ProfileFactory::_from_profile) >>>>>>>> > Jan 18 14:55:28 pf4 httpd.aaa-docker-wrapper[2299]: >>>>>>>> httpd.aaa(7) >>>>>>>> > INFO: [mac:f2:ef:bb:22:8c:62] Found authentication >>>>>>>> source(s) : >>>>>>>> > '' for realm 'null' >>>>>>>> > (pf::config::util::filter_authentication_sources) >>>>>>>> > Jan 18 14:55:28 pf4 httpd.aaa-docker-wrapper[2299]: >>>>>>>> httpd.aaa(7) >>>>>>>> > INFO: [mac:f2:ef:bb:22:8c:62] Connection type is MAC-AUTH. >>>>>>>> > Getting role from node_info (pf::role::getRegisteredRole) >>>>>>>> > Jan 18 14:55:28 pf4 httpd.aaa-docker-wrapper[2299]: >>>>>>>> httpd.aaa(7) >>>>>>>> > INFO: [mac:f2:ef:bb:22:8c:62] Username was defined >>>>>>>> > "f2efbb228c62" - returning role 'guest' >>>>>>>> > (pf::role::getRegisteredRole) >>>>>>>> > Jan 18 14:55:28 pf4 httpd.aaa-docker-wrapper[2299]: >>>>>>>> httpd.aaa(7) >>>>>>>> > INFO: [mac:f2:ef:bb:22:8c:62] PID: "en...@gm... >>>>>>>> > <mailto:en...@gm...>", Status: reg Returned VLAN: >>>>>>>> > (undefined), Role: guest (pf::role::fetchRoleForNode) >>>>>>>> > Jan 18 *14:55:28* pf4 httpd.aaa-docker-wrapper[2299]: >>>>>>>> > httpd.aaa(7) INFO: [mac:f2:ef:bb:22:8c:62] *(10.2.1.11) >>>>>>>> Added >>>>>>>> > VLAN 83 to the returned RADIUS Access-Accept >>>>>>>> > (pf::Switch::returnRadiusAccessAccept)* >>>>>>>> > Jan 18 14:55:29 pf4 httpd.aaa-docker-wrapper[2299]: >>>>>>>> httpd.aaa(7) >>>>>>>> > INFO: [mac:f2:ef:bb:22:8c:62] Updating locationlog from >>>>>>>> > accounting request (pf::api::handle_accounting_metadata) >>>>>>>> > Jan 18 14:55:29 pf4 httpd.aaa-docker-wrapper[2299]: >>>>>>>> httpd.aaa(7) >>>>>>>> > WARN: [mac:f2:ef:bb:22:8c:62] Cannot find any combination >>>>>>>> ID in >>>>>>>> > any schemas >>>>>>>> (fingerbank::Source::LocalDB::_getCombinationID) >>>>>>>> > Jan 18 14:55:29 pf4 httpd.aaa-docker-wrapper[2299]: >>>>>>>> httpd.aaa(7) >>>>>>>> > INFO: [mac:f2:ef:bb:22:8c:62] Upstream is configured and >>>>>>>> unable >>>>>>>> > to fullfil an exact match locally. Will ignore result >>>>>>>> from local >>>>>>>> > database (fingerbank::Source::LocalDB::match) >>>>>>>> > Jan 18 14:55:29 pf4 httpd.aaa-docker-wrapper[2299]: >>>>>>>> httpd.aaa(7) >>>>>>>> > INFO: [mac:f2:ef:bb:22:8c:62] Successfully interrogate >>>>>>>> upstream >>>>>>>> > Fingerbank project for matching. Got device : 264 >>>>>>>> > (fingerbank::Source::Collector::match) >>>>>>>> > Jan 18 14:55:29 pf4 httpd.aaa-docker-wrapper[2299]: >>>>>>>> httpd.aaa(7) >>>>>>>> > WARN: [mac:f2:ef:bb:22:8c:62] Unable to pull accounting >>>>>>>> history >>>>>>>> > for device f2:ef:bb:22:8c:62. The history set doesn't >>>>>>>> exist yet. >>>>>>>> > (pf::accounting_events_history::latest_mac_history) >>>>>>>> > Jan 18 14:55:29 pf4 pfqueue[64775]: pfqueue(64775) INFO: >>>>>>>> > [mac:f2:ef:bb:22:8c:62] Sending a firewall SSO 'Update' >>>>>>>> request >>>>>>>> > for MAC 'f2:ef:bb:22:8c:62' and IP '10.2.2.178' >>>>>>>> > (pf::firewallsso::do_sso) >>>>>>>> > Jan 18 14:55:29 pf4 pfqueue[65705]: pfqueue(65705) INFO: >>>>>>>> > [mac:f2:ef:bb:22:8c:62] Instantiate profile Test_WiFi >>>>>>>> > (pf::Connection::ProfileFactory::_from_profile) >>>>>>>> > >>>>>>>> > >>>>>>>> > We see the VLAN change initiated from PF applied in the >>>>>>>> NAS/AP >>>>>>>> > logs and the client connection onto the Default VLAN 83 >>>>>>>> > >>>>>>>> > Wed Jan 18 14:55:28 2023 daemon.notice hostapd: wlan0: >>>>>>>> > AP-STA-DISCONNECTED f2:ef:bb:22:8c:62 >>>>>>>> > Wed Jan 18 14:55:28 2023 daemon.info <http://daemon.info> >>>>>>>> > hostapd: wlan0: STA f2:ef:bb:22:8c:62 RADIUS: stopped >>>>>>>> accounting >>>>>>>> > session 2DB2C59D34BD1998 >>>>>>>> > Wed Jan 18 *14:55:28* 2023 daemon.info < >>>>>>>> http://daemon.info> >>>>>>>> > hostapd: wlan0: STA f2:ef:bb:22:8c:62 RADIUS: *VLAN ID 83* >>>>>>>> > Wed Jan 18 14:55:29 2023 daemon.info <http://daemon.info> >>>>>>>> > hostapd: wlan0: STA f2:ef:bb:22:8c:62 IEEE 802.11: >>>>>>>> authenticated >>>>>>>> > Wed Jan 18 14:55:29 2023 daemon.info <http://daemon.info> >>>>>>>> > hostapd: wlan0: STA f2:ef:bb:22:8c:62 IEEE 802.11: >>>>>>>> associated >>>>>>>> > (aid 2) >>>>>>>> > Wed Jan 18 *14:55:29* 2023 daemon.notice hostapd: wlan0: >>>>>>>> > *AP-STA-CONNECTED f2:ef:bb:22:8c:62* >>>>>>>> > Wed Jan 18 14:55:29 2023 daemon.info <http://daemon.info> >>>>>>>> > hostapd: wlan0: STA f2:ef:bb:22:8c:62 RADIUS: starting >>>>>>>> > accounting session 2DB2C59D34BD1998 >>>>>>>> > >>>>>>>> > With matching tcpdump capture showing the Disconnect and >>>>>>>> ACK >>>>>>>> > from the NAS/AP >>>>>>>> > >>>>>>>> > *14:55:28*.794094 IP 10.2.1.2.44286 > 10.2.1.11.3799: >>>>>>>> RADIUS, >>>>>>>> > *Disconnect-Request* (40), id: 0x7d length: 39 >>>>>>>> > 14:55:28.795785 IP 10.2.1.11.48577 > 10.2.1.2.1813: >>>>>>>> RADIUS, >>>>>>>> > Accounting-Request (4), id: 0x1e length: 224 >>>>>>>> > *14:55:28*.796071 IP 10.2.1.11.3799 > 10.2.1.2.44286: >>>>>>>> RADIUS, >>>>>>>> > *Disconnect-ACK* (41), id: 0x7d length: 44 >>>>>>>> > 14:55:28.796386 IP 10.2.1.2.1813 > 10.2.1.11.48577: >>>>>>>> RADIUS, >>>>>>>> > Accounting-Response (5), id: 0x1e length: 35 >>>>>>>> > 14:55:28.885006 IP 10.2.1.11.49421 > 10.2.1.2.1812: >>>>>>>> RADIUS, >>>>>>>> > Access-Request (1), id: 0x1f length: 164 >>>>>>>> > 14:55:28.920956 IP 10.2.1.2.1812 > 10.2.1.11.49421: >>>>>>>> RADIUS, >>>>>>>> > Access-Accept (2), id: 0x1f length: 36 >>>>>>>> > 14:55:29.075666 IP 10.2.1.11.48577 > 10.2.1.2.1813: >>>>>>>> RADIUS, >>>>>>>> > Accounting-Request (4), id: 0x20 length: 182 >>>>>>>> > 14:55:29.076067 IP 10.2.1.2.1813 > 10.2.1.11.48577: >>>>>>>> RADIUS, >>>>>>>> > Accounting-Response (5), id: 0x20 length: 35 >>>>>>>> > >>>>>>>> > At this point the client is now on the Default VLAN 83 >>>>>>>> as of >>>>>>>> > 14:55:29 >>>>>>>> > >>>>>>>> > On our Default Network, we immediately start to see >>>>>>>> traffic from >>>>>>>> > the client. The issue seems to be that the client is >>>>>>>> still >>>>>>>> > using the IP from the Registration network (10.2.2.178); >>>>>>>> Almost >>>>>>>> > like it did not detect the wifi disconnect and reconnect. >>>>>>>> > It should be on a 10.2.4.0/24 <http://10.2.4.0/24> IP >>>>>>>> address >>>>>>>> > >>>>>>>> > tcpdump: listening on eth1, link-type EN10MB (Ethernet), >>>>>>>> capture >>>>>>>> > size 262144 bytes >>>>>>>> > 14:55:29.071416 f2:ef:bb:22:8c:62 (oui Unknown) > >>>>>>>> Broadcast Null >>>>>>>> > Unnumbered, xid, Flags [Response], length 42: 01 00 >>>>>>>> > 14:55:29.725195 IP (tos 0x0, ttl 64, id 0, offset 0, >>>>>>>> flags [DF], >>>>>>>> > proto TCP (6), length 64) >>>>>>>> > *10.2.2.178*.62377 > web.inverse.ca.80: Flags [S], cksum >>>>>>>> 0x1fc6 >>>>>>>> > (correct), seq 1176141384, win 65535, options [mss >>>>>>>> > 1460,nop,wscale 6,nop,nop,TS val 2334978519 ecr >>>>>>>> 0,sackOK,eol], >>>>>>>> > length 0 >>>>>>>> > 14:55:29.725195 IP (tos 0x0, ttl 64, id 0, offset 0, >>>>>>>> flags [DF], >>>>>>>> > proto TCP (6), length 64) >>>>>>>> > 10.2.2.178.62374 > web.inverse.ca.80: Flags [S], >>>>>>>> cksum >>>>>>>> > 0x231d (correct), seq 1612822294, win 65535, options [mss >>>>>>>> > 1460,nop,wscale 6,nop,nop,TS val 1377096902 ecr >>>>>>>> 0,sackOK,eol], >>>>>>>> > length 0 >>>>>>>> > 14:55:29.726606 IP (tos 0x0, ttl 64, id 0, offset 0, >>>>>>>> flags [DF], >>>>>>>> > proto TCP (6), length 64) >>>>>>>> > 10.2.2.178.62372 > web.inverse.ca.80: Flags [S], >>>>>>>> cksum >>>>>>>> > 0x8e90 (correct), seq 2169278132, win 65535, options [mss >>>>>>>> > 1460,nop,wscale 6,nop,nop,TS val 1248622644 ecr >>>>>>>> 0,sackOK,eol], >>>>>>>> > length 0 >>>>>>>> > 14:55:29.728233 IP (tos 0x0, ttl 64, id 0, offset 0, >>>>>>>> flags [DF], >>>>>>>> > proto TCP (6), length 64) >>>>>>>> > .... >>>>>>>> > >>>>>>>> > The client gets to the end of the captive portal >>>>>>>> connection >>>>>>>> > progress bar, and gets an obvious error, because it has >>>>>>>> not >>>>>>>> > requested a new IP, as seen in the tcpdump, with th... [truncated message content] |