NAC portal for wifi-users: UserNames are not displayed in XMC>>Wirelles>>Clients

  • 0
  • 1
  • Problem
  • Updated 2 months ago
  • Solved
Hello, team,

I've partially configured V2110&NAC integration. There is a webportal on NAC, where wireless users login using their AD credentials.

The main goal of this configuration was to get an ability to see AD usernames in XMC >> Wireless >> Clients.

But now I see just IPs, MACs, Device Types and nothing more for authorized clients. How can I fix it?

Also, I've experienced the following issues during authorization process:

1) When I use iPhone to connect to SSID, it gets me to the NAC's webportal, but it is displayed just about 10 seconds. If I input credentials in this time, everything is ok I get registration, if I input it more than 10 sec, iphone brings me back to SSIDs list. WTF? With Nokia Lumia 950 it works perfectly well without time limits.
2) When I use Windows 10 laptop I get "Endless registration" on NAC webportal in browser, but in spite of this, I get access to network also.

What should I do to fix it? 

1) I need to have enough time to input credentials on Apples
2) I want to avoid "Endless registration" message on laptops.

Please, help!

Many thanks in advance,
Ilya

There are some logs&pics below:





It's for Endless registration from laptop:

Tue Jul 10 18:04:02 2018 : Info: Debugger not attached

Tue Jul 10 18:04:03 2018 : Info: [etsnac connection_mgr] Successfully connected to port: 1300 on server 127.0.0.1 from client port: 0

Tue Jul 10 18:04:03 2018 : Info: [etsnac server_process] Resetting diagnostics (debug_level: 1, rad_debug_lvl: 3, fr_debug_lvl: 3, log_serialization: disabled, log_mutex: disabled, log_nrm_cleanup: disabled, log_pword: disabled, log_auth: disabled, log_auth_goodpass: disabled, log_auth_badpass: disabled

Tue Jul 10 18:04:03 2018 : Info: [etsnac server_process] Resetting response attr count to: 3

Tue Jul 10 18:04:03 2018 : Debug: [etsnac server_process] response attr (1): 11 - Filter-Id

Tue Jul 10 18:04:03 2018 : Debug: [etsnac server_process] response attr (2): 63 - Login-LAT-Port

Tue Jul 10 18:04:03 2018 : Debug: [etsnac server_process] response attr (3): 6 - Service-Type

Tue Jul 10 18:04:03 2018 : Info: [etsnac server_process] Resetting remove attr count to: 4

Tue Jul 10 18:04:03 2018 : Debug: [etsnac server_process] remove attr (1): 57 - MS-Extended-Quarantine-State

Tue Jul 10 18:04:03 2018 : Debug: [etsnac server_process] remove attr (2): 50 - MS-Machine-Name

Tue Jul 10 18:04:03 2018 : Debug: [etsnac server_process] remove attr (3): 45 - MS-Quarantine-State

Tue Jul 10 18:04:03 2018 : Debug: [etsnac server_process] remove attr (4): 54 - MS-RNAP-Not-Quarantine-Capable

Tue Jul 10 18:04:03 2018 : Info: [etsnac server_process] Resetting proxy attr count to: 0

Tue Jul 10 18:04:03 2018 : Debug: [etsnac connection_mgr] Releasing authentication server connection ID: 31.

Tue Jul 10 18:04:03 2018 : Info: [etsnac] Starting Extreme Networks NAC module version: 10, Feb 14 2018 13:45:46

Tue Jul 10 18:04:03 2018 : Debug: # Instantiating module "expiration" from file /opt/nac/radius/raddb/mods-enabled/expiration

Tue Jul 10 18:04:03 2018 : Debug: # Instantiating module "attr_filter.post-proxy" from file /opt/nac/radius/raddb/mods-enabled/attr_filter

Tue Jul 10 18:04:03 2018 : Debug: reading pairlist file /opt/nac/radius/raddb/mods-config/attr_filter/post-proxy

Tue Jul 10 18:04:03 2018 : Debug: # Instantiating module "attr_filter.pre-proxy" from file /opt/nac/radius/raddb/mods-enabled/attr_filter

Tue Jul 10 18:04:03 2018 : Debug: reading pairlist file /opt/nac/radius/raddb/mods-config/attr_filter/pre-proxy

Tue Jul 10 18:04:03 2018 : Debug: # Instantiating module "attr_filter.access_reject" from file /opt/nac/radius/raddb/mods-enabled/attr_filter

Tue Jul 10 18:04:03 2018 : Debug: reading pairlist file /opt/nac/radius/raddb/mods-config/attr_filter/access_reject

Tue Jul 10 18:04:03 2018 : Debug: # Instantiating module "attr_filter.access_challenge" from file /opt/nac/radius/raddb/mods-enabled/attr_filter

Tue Jul 10 18:04:03 2018 : Debug: reading pairlist file /opt/nac/radius/raddb/mods-config/attr_filter/access_challenge

Tue Jul 10 18:04:03 2018 : Debug: # Instantiating module "attr_filter.accounting_response" from file /opt/nac/radius/raddb/mods-enabled/attr_filter

Tue Jul 10 18:04:03 2018 : Debug: reading pairlist file /opt/nac/radius/raddb/mods-config/attr_filter/accounting_response

Tue Jul 10 18:04:03 2018 : Debug: # Instantiating module "pap" from file /opt/nac/radius/raddb/mods-enabled/pap

Tue Jul 10 18:04:03 2018 : Debug: # Instantiating module "preprocess" from file /opt/nac/radius/raddb/mods-enabled/preprocess

Tue Jul 10 18:04:03 2018 : Debug: reading pairlist file /opt/nac/radius/raddb/mods-config/preprocess/huntgroups

Tue Jul 10 18:04:03 2018 : Debug: reading pairlist file /opt/nac/radius/raddb/mods-config/preprocess/hints

Tue Jul 10 18:04:03 2018 : Debug: # Instantiating module "mschap" from file /opt/nac/radius/raddb/mods-enabled/mschap

Tue Jul 10 18:04:03 2018 : Debug: rlm_mschap (mschap): authenticating by calling 'ntlm_auth'

Tue Jul 10 18:04:03 2018 : Debug: } # modules

Tue Jul 10 18:04:03 2018 : Debug: radiusd: #### Loading Virtual Servers ####

Tue Jul 10 18:04:03 2018 : Debug: server { # from file /opt/nac/radius/raddb/radiusd.conf

Tue Jul 10 18:04:03 2018 : Debug: } # server

Tue Jul 10 18:04:03 2018 : Debug: server nac-server { # from file /opt/nac/radius/raddb/sites-enabled/nac-server

Tue Jul 10 18:04:03 2018 : Debug: # Loading authenticate {...}

Tue Jul 10 18:04:03 2018 : Debug: eap

Tue Jul 10 18:04:03 2018 : Debug: # Loading authorize {...}

Tue Jul 10 18:04:03 2018 : Warning: /opt/nac/radius/raddb/sites-enabled/nac-server[44]: Please change attribute reference to '&Load-Balance-Key = ...'

Tue Jul 10 18:04:03 2018 : Debug: update {

Tue Jul 10 18:04:03 2018 : Debug: &control:Load-Balance-Key = "%{Calling-Station-Id}"

Tue Jul 10 18:04:03 2018 : Debug: }

Tue Jul 10 18:04:03 2018 : Debug: etsnac

Tue Jul 10 18:04:03 2018 : Debug: chap

Tue Jul 10 18:04:03 2018 : Debug: mschap

Tue Jul 10 18:04:03 2018 : Debug: eap

Tue Jul 10 18:04:03 2018 : Debug: pap

Tue Jul 10 18:04:03 2018 : Debug: # Loading preacct {...}

Tue Jul 10 18:04:03 2018 : Warning: /opt/nac/radius/raddb/policy.d/accounting[37]: Please change attribute reference to '&Acct-Unique-Session-Id := ...'

Tue Jul 10 18:04:03 2018 : Warning: /opt/nac/radius/raddb/policy.d/accounting[49]: Please change attribute reference to '&Acct-Unique-Session-Id := ...'

Tue Jul 10 18:04:03 2018 : Debug: policy acct_unique {

Tue Jul 10 18:04:03 2018 : Debug: if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/) {

Tue Jul 10 18:04:03 2018 : Debug: update {

Tue Jul 10 18:04:03 2018 : Debug: &Acct-Unique-Session-Id := "%{md5:%{1},%{Acct-Session-ID}}"

Tue Jul 10 18:04:03 2018 : Debug: }

Tue Jul 10 18:04:03 2018 : Debug: }

Tue Jul 10 18:04:03 2018 : Debug: else {

Tue Jul 10 18:04:03 2018 : Debug: update {

Tue Jul 10 18:04:03 2018 : Debug: &Acct-Unique-Session-Id := "%{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}"

Tue Jul 10 18:04:03 2018 : Debug: }

Tue Jul 10 18:04:03 2018 : Debug: }

Tue Jul 10 18:04:03 2018 : Debug: }

Tue Jul 10 18:04:03 2018 : Debug: etsnac

Tue Jul 10 18:04:03 2018 : Debug: # Loading accounting {...}

Tue Jul 10 18:04:03 2018 : Debug: etsnac

Tue Jul 10 18:04:03 2018 : Debug: # Loading session {...}

Tue Jul 10 18:04:03 2018 : Debug: radutmp

Tue Jul 10 18:04:03 2018 : Debug: # Loading pre-proxy {...}

Tue Jul 10 18:04:03 2018 : Debug: etsnac

Tue Jul 10 18:04:03 2018 : Debug: # Loading post-proxy {...}

Tue Jul 10 18:04:03 2018 : Debug: etsnac

Tue Jul 10 18:04:03 2018 : Debug: eap

Tue Jul 10 18:04:03 2018 : Debug: # Loading post-auth {...}

Tue Jul 10 18:04:03 2018 : Debug: etsnac

Tue Jul 10 18:04:03 2018 : Debug: } # server nac-server

Tue Jul 10 18:04:03 2018 : Debug: server nac-inner-tunnel { # from file /opt/nac/radius/raddb/sites-enabled/nac-inner-tunnel

Tue Jul 10 18:04:03 2018 : Debug: # Loading authenticate {...}

Tue Jul 10 18:04:03 2018 : Warning: /opt/nac/radius/raddb/sites-enabled/nac-inner-tunnel[41]: Please change attribute reference to '&Module-Failure-Message = ...'

Tue Jul 10 18:04:03 2018 : Debug: eap

Tue Jul 10 18:04:03 2018 : Debug: # Loading authorize {...}

Tue Jul 10 18:04:03 2018 : Debug: ets_tunnel

Tue Jul 10 18:04:03 2018 : Debug: chap

Tue Jul 10 18:04:03 2018 : Debug: mschap

Tue Jul 10 18:04:03 2018 : Debug: eap

Tue Jul 10 18:04:03 2018 : Debug: pap

Tue Jul 10 18:04:03 2018 : Debug: # Loading session {...}

Tue Jul 10 18:04:03 2018 : Debug: radutmp

Tue Jul 10 18:04:03 2018 : Debug: # Loading post-auth {...}

Tue Jul 10 18:04:03 2018 : Warning: /opt/nac/radius/raddb/sites-enabled/nac-inner-tunnel[57]: Please change attribute reference to '&Module-Failure-Message := ...'

Tue Jul 10 18:04:03 2018 : Debug: ets_tunnel

Tue Jul 10 18:04:03 2018 : Debug: } # server nac-inner-tunnel

Tue Jul 10 18:04:03 2018 : Debug: server nac-proxy-failed { # from file /opt/nac/radius/raddb/sites-enabled/nac-proxy-failed

Tue Jul 10 18:04:03 2018 : Debug: # Loading authenticate {...}

Tue Jul 10 18:04:03 2018 : Debug: ets_proxy_failed

Tue Jul 10 18:04:03 2018 : Debug: # Loading authorize {...}

Tue Jul 10 18:04:03 2018 : Debug: ets_proxy_failed

Tue Jul 10 18:04:03 2018 : Debug: } # server nac-proxy-failed

Tue Jul 10 18:04:03 2018 : Debug: thread pool {

Tue Jul 10 18:04:03 2018 : Debug: start_servers = 5

Tue Jul 10 18:04:03 2018 : Debug: max_servers = 32

Tue Jul 10 18:04:03 2018 : Debug: min_spare_servers = 3

Tue Jul 10 18:04:03 2018 : Debug: max_spare_servers = 10

Tue Jul 10 18:04:03 2018 : Debug: max_requests_per_server = 3000

Tue Jul 10 18:04:03 2018 : Debug: cleanup_delay = 5

Tue Jul 10 18:04:03 2018 : Debug: max_queue_size = 65536

Tue Jul 10 18:04:03 2018 : Debug: auto_limit_acct = no

Tue Jul 10 18:04:03 2018 : Debug: }

Tue Jul 10 18:04:03 2018 : Debug: Thread spawned new child 1. Total threads in pool: 1

Tue Jul 10 18:04:03 2018 : Debug: Thread 1 waiting to be assigned a request

Tue Jul 10 18:04:03 2018 : Debug: Thread spawned new child 2. Total threads in pool: 2

Tue Jul 10 18:04:03 2018 : Debug: Thread 2 waiting to be assigned a request

Tue Jul 10 18:04:03 2018 : Debug: Thread 3 waiting to be assigned a request

Tue Jul 10 18:04:03 2018 : Debug: Thread spawned new child 3. Total threads in pool: 3

Tue Jul 10 18:04:03 2018 : Debug: Thread spawned new child 4. Total threads in pool: 4

Tue Jul 10 18:04:03 2018 : Debug: Thread 4 waiting to be assigned a request

Tue Jul 10 18:04:03 2018 : Debug: Thread spawned new child 5. Total threads in pool: 5

Tue Jul 10 18:04:03 2018 : Debug: Thread 5 waiting to be assigned a request

Tue Jul 10 18:04:03 2018 : Debug: Thread pool initialized

Tue Jul 10 18:04:03 2018 : Debug: radiusd: #### Opening IP addresses and Ports ####

Tue Jul 10 18:04:03 2018 : Debug: listen {

Tue Jul 10 18:04:03 2018 : Debug: type = "auth"

Tue Jul 10 18:04:03 2018 : Debug: ipaddr = 192.168.1.200

Tue Jul 10 18:04:03 2018 : Debug: port = 1812

Tue Jul 10 18:04:03 2018 : Debug: limit {

Tue Jul 10 18:04:03 2018 : Debug: max_connections = 16

Tue Jul 10 18:04:03 2018 : Debug: lifetime = 0

Tue Jul 10 18:04:03 2018 : Debug: idle_timeout = 30

Tue Jul 10 18:04:03 2018 : Debug: }

Tue Jul 10 18:04:03 2018 : Debug: }

Tue Jul 10 18:04:03 2018 : Debug: listen {

Tue Jul 10 18:04:03 2018 : Debug: type = "acct"

Tue Jul 10 18:04:03 2018 : Debug: ipaddr = 192.168.1.200

Tue Jul 10 18:04:03 2018 : Debug: port = 1813

Tue Jul 10 18:04:03 2018 : Debug: limit {

Tue Jul 10 18:04:03 2018 : Debug: max_connections = 16

Tue Jul 10 18:04:03 2018 : Debug: lifetime = 0

Tue Jul 10 18:04:03 2018 : Debug: idle_timeout = 30

Tue Jul 10 18:04:03 2018 : Debug: }

Tue Jul 10 18:04:03 2018 : Debug: }

Tue Jul 10 18:04:03 2018 : Debug: listen {

Tue Jul 10 18:04:03 2018 : Debug: type = "auth"

Tue Jul 10 18:04:03 2018 : Debug: ipaddr = 127.0.0.1

Tue Jul 10 18:04:03 2018 : Debug: port = 18120

Tue Jul 10 18:04:03 2018 : Debug: }

Tue Jul 10 18:04:03 2018 : Debug: Listening on auth address 192.168.1.200 port 1812 bound to server nac-server

Tue Jul 10 18:04:03 2018 : Debug: Listening on acct address 192.168.1.200 port 1813 bound to server nac-server

Tue Jul 10 18:04:03 2018 : Debug: Listening on auth address 127.0.0.1 port 18120 bound to server nac-inner-tunnel

Tue Jul 10 18:04:03 2018 : Debug: Opened new proxy socket 'proxy address * port 40433'

Tue Jul 10 18:04:03 2018 : Debug: Listening on proxy address * port 40433

Tue Jul 10 18:04:03 2018 : Info: Ready to process requests

Tue Jul 10 18:04:41 2018 : Debug: Threads: total/active/spare threads = 5/0/5

Tue Jul 10 18:04:41 2018 : Debug: Waking up in 0.3 seconds.

Tue Jul 10 18:04:41 2018 : Debug: Thread 5 got semaphore

Tue Jul 10 18:04:41 2018 : Debug: Thread 5 handling request 0, (1 handled so far)

Tue Jul 10 18:04:41 2018 : Debug: (0) Received Access-Request Id 110 from 192.168.1.111:33867 to 192.168.1.200:1812 length 259

Tue Jul 10 18:04:41 2018 : Debug: (0) User-Name = "88B111C3EDFD"

Tue Jul 10 18:04:41 2018 : Debug: (0) User-Password = "88B111C3EDFD"

Tue Jul 10 18:04:41 2018 : Debug: (0) NAS-IP-Address = 127.0.0.1

Tue Jul 10 18:04:41 2018 : Debug: (0) NAS-Port = 101

Tue Jul 10 18:04:41 2018 : Debug: (0) NAS-Port-Type = Wireless-Other

Tue Jul 10 18:04:41 2018 : Debug: (0) NAS-Identifier = "SupportVO"

Tue Jul 10 18:04:41 2018 : Debug: (0) Siemens-AP-Serial = "15141805085D0000"

Tue Jul 10 18:04:41 2018 : Debug: (0) Siemens-AP-Name = "15141805085D0000"

Tue Jul 10 18:04:41 2018 : Debug: (0) Siemens-VNS-Name = "SupportVO"

Tue Jul 10 18:04:41 2018 : Debug: (0) Siemens-SSID = "SupportVO"

Tue Jul 10 18:04:41 2018 : Debug: (0) Siemens-BSS-MAC = "D88466272BF0"

Tue Jul 10 18:04:41 2018 : Debug: (0) Siemens-Policy-Name = "Non Authenticated"

Tue Jul 10 18:04:41 2018 : Debug: (0) Calling-Station-Id = "88B111C3EDFD"

Tue Jul 10 18:04:41 2018 : Debug: (0) Called-Station-Id = "D88466272BF0"

Tue Jul 10 18:04:41 2018 : Debug: (0) Acct-Session-Id = "M3153457a0002"

Tue Jul 10 18:04:41 2018 : Debug: (0) session-state: No State attribute

Tue Jul 10 18:04:41 2018 : Debug: (0) # Executing section authorize from file /opt/nac/radius/raddb/sites-enabled/nac-server

Tue Jul 10 18:04:41 2018 : Debug: (0) authorize {

Tue Jul 10 18:04:41 2018 : Debug: (0) update control {

Tue Jul 10 18:04:41 2018 : Debug: (0) EXPAND %{Calling-Station-Id}

Tue Jul 10 18:04:41 2018 : Debug: (0) --> 88B111C3EDFD

Tue Jul 10 18:04:41 2018 : Debug: (0) Load-Balance-Key = 88B111C3EDFD

Tue Jul 10 18:04:41 2018 : Debug: (0) } # update control = noop

Tue Jul 10 18:04:41 2018 : Debug: (0) modsingle[authorize]: calling etsnac (rlm_etsnac) for request 0

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac] *NOT* Continuing proxied conversation, skipping...

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac nac_request_mgr] Generated MAC 88b111c3edfd from Calling-Station-Id: 88B111C3EDFD

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac nac_request_mgr] Found username from: User-Name: 88B111C3EDFD

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac nac_request_mgr] Found User-Password attribute: 2, setting auth type to: PAP

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac nac_request_mgr] Found switch ip from: NAS-IP-Address: 127.0.0.1

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac nac_request_mgr] Unable to find existing NAC request manager instance.

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac nac_request_mgr] Making a new request to the AAA server for request ID: 0

Tue Jul 10 18:04:41 2018 : Info: (0) [etsnac connection_mgr] AAA Request [ID: 0, Source IP: 192.168.1.111, Command: Authenticate & Authorize Request(0x02)]

(0) --- Request VPs ---

(0) User-Name = "88B111C3EDFD"

(0) User-Password = ************

(0) NAS-IP-Address = 127.0.0.1

(0) NAS-Port = 101

(0) NAS-Port-Type = Wireless-Other

(0) NAS-Identifier = "SupportVO"

(0) Siemens-AP-Serial = "15141805085D0000"

(0) Siemens-AP-Name = ****************

(0) Siemens-VNS-Name = "SupportVO"

(0) Siemens-SSID = "SupportVO"

(0) Siemens-BSS-MAC = "D88466272BF0"

(0) Siemens-Policy-Name = "Non Authenticated"

(0) Calling-Station-Id = "88B111C3EDFD"

(0) Called-Station-Id = "D88466272BF0"

(0) Acct-Session-Id = "M3153457a0002"

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac connection_mgr] Using authentication server connection ID: 31.

Tue Jul 10 18:04:41 2018 : Info: (0) [etsnac connection_mgr] AAA Response [ID: 0, Command: Accept User(0x22)]

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac connection_mgr] Releasing authentication server connection ID: 31.

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac nac_request_mgr] Unable to find existing NAC request manager instance.

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac] The AAA server says to accept the request.

Tue Jul 10 18:04:41 2018 : Debug: (0) modsingle[authorize]: returned from etsnac (rlm_etsnac) for request 0

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac] = ok

Tue Jul 10 18:04:41 2018 : Debug: (0) modsingle[authorize]: calling chap (rlm_chap) for request 0

Tue Jul 10 18:04:41 2018 : Debug: (0) modsingle[authorize]: returned from chap (rlm_chap) for request 0

Tue Jul 10 18:04:41 2018 : Debug: (0) [chap] = noop

Tue Jul 10 18:04:41 2018 : Debug: (0) modsingle[authorize]: calling mschap (rlm_mschap) for request 0

Tue Jul 10 18:04:41 2018 : Debug: (0) modsingle[authorize]: returned from mschap (rlm_mschap) for request 0

Tue Jul 10 18:04:41 2018 : Debug: (0) [mschap] = noop

Tue Jul 10 18:04:41 2018 : Debug: (0) modsingle[authorize]: calling eap (rlm_eap) for request 0

Tue Jul 10 18:04:41 2018 : Debug: (0) eap: No EAP-Message, not doing EAP

Tue Jul 10 18:04:41 2018 : Debug: (0) modsingle[authorize]: returned from eap (rlm_eap) for request 0

Tue Jul 10 18:04:41 2018 : Debug: (0) [eap] = noop

Tue Jul 10 18:04:41 2018 : Debug: (0) modsingle[authorize]: calling pap (rlm_pap) for request 0

Tue Jul 10 18:04:41 2018 : WARNING: (0) pap: Auth-Type already set. Not setting to PAP

Tue Jul 10 18:04:41 2018 : Debug: (0) modsingle[authorize]: returned from pap (rlm_pap) for request 0

Tue Jul 10 18:04:41 2018 : Debug: (0) [pap] = noop

Tue Jul 10 18:04:41 2018 : Debug: (0) } # authorize = ok

Tue Jul 10 18:04:41 2018 : Debug: (0) Found Auth-Type = Accept

Tue Jul 10 18:04:41 2018 : Debug: (0) Auth-Type = Accept, accepting the user

Tue Jul 10 18:04:41 2018 : Debug: (0) # Executing section post-auth from file /opt/nac/radius/raddb/sites-enabled/nac-server

Tue Jul 10 18:04:41 2018 : Debug: (0) post-auth {

Tue Jul 10 18:04:41 2018 : Debug: (0) modsingle[post-auth]: calling etsnac (rlm_etsnac) for request 0

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac] Processing Response-Packet-Type Access-Accept(2)

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac] Not running EAP-TLS User-Name replacement for non EAP authentication

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac nac_request_mgr] Generated MAC 88b111c3edfd from Calling-Station-Id: 88B111C3EDFD

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac nac_request_mgr] Found username from: User-Name: 88B111C3EDFD

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac nac_request_mgr] Found User-Password attribute: 2, setting auth type to: PAP

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac nac_request_mgr] Found switch ip from: NAS-IP-Address: 127.0.0.1

Tue Jul 10 18:04:41 2018 : Info: (0) [etsnac connection_mgr] AAA Request [ID: 0, Source IP: 192.168.1.111, Command: Post Authorize Request(0x03)]

(0) --- Request VPs ---

(0) User-Name = "88B111C3EDFD"

(0) User-Password = ************

(0) NAS-IP-Address = 127.0.0.1

(0) NAS-Port = 101

(0) NAS-Port-Type = Wireless-Other

(0) NAS-Identifier = "SupportVO"

(0) Siemens-AP-Serial = "15141805085D0000"

(0) Siemens-AP-Name = ****************

(0) Siemens-VNS-Name = "SupportVO"

(0) Siemens-SSID = "SupportVO"

(0) Siemens-BSS-MAC = "D88466272BF0"

(0) Siemens-Policy-Name = "Non Authenticated"

(0) Calling-Station-Id = "88B111C3EDFD"

(0) Called-Station-Id = "D88466272BF0"

(0) Acct-Session-Id = "M3153457a0002"

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac connection_mgr] Using authentication server connection ID: 31.

Tue Jul 10 18:04:41 2018 : Info: (0) [etsnac connection_mgr] AAA Response [ID: 0, Command: Replace Response Attributes(0x27)]

(0) Filter-Id := "Enterasys:version=1:policy=Unregistered"

(0) Login-LAT-Port := "0"

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac connection_mgr] Releasing authentication server connection ID: 31.

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac] The AAA server says to replace the response attributes.

Tue Jul 10 18:04:41 2018 : Debug: (0) modsingle[post-auth]: returned from etsnac (rlm_etsnac) for request 0

Tue Jul 10 18:04:41 2018 : Debug: (0) [etsnac] = updated

Tue Jul 10 18:04:41 2018 : Debug: (0) } # post-auth = updated

Tue Jul 10 18:04:41 2018 : Debug: (0) Sent Access-Accept Id 110 from 192.168.1.200:1812 to 192.168.1.111:33867 length 0

Tue Jul 10 18:04:41 2018 : Debug: (0) Filter-Id := "Enterasys:version=1:policy=Unregistered"

Tue Jul 10 18:04:41 2018 : Debug: (0) Login-LAT-Port := "0"

Tue Jul 10 18:04:41 2018 : Debug: (0) Finished request

Tue Jul 10 18:04:41 2018 : Debug: Thread 5 waiting to be assigned a request

Tue Jul 10 18:04:41 2018 : Debug: Waking up in 4.7 seconds.

Tue Jul 10 18:04:46 2018 : Debug: (0) Cleaning up request packet ID 110 with timestamp +38

Tue Jul 10 18:04:46 2018 : Info: Ready to process requests

Tue Jul 10 18:07:00 2018 : Debug: Waking up in 0.3 seconds.

Tue Jul 10 18:07:00 2018 : Debug: Thread 4 got semaphore

Tue Jul 10 18:07:00 2018 : Debug: Thread 4 handling request 1, (1 handled so far)

Tue Jul 10 18:07:00 2018 : Debug: (1) Received Accounting-Request Id 0 from 192.168.1.111:49438 to 192.168.1.200:1813 length 364

Tue Jul 10 18:07:00 2018 : Debug: (1) Acct-Session-Id = "M3153457a0002"

Tue Jul 10 18:07:00 2018 : Debug: (1) NAS-Port = 101

Tue Jul 10 18:07:00 2018 : Debug: (1) User-Name = "88B111C3EDFD"

Tue Jul 10 18:07:00 2018 : Debug: (1) Filter-Id = "Enterprise User"

Tue Jul 10 18:07:00 2018 : Debug: (1) Acct-Interim-Interval = 1800

Tue Jul 10 18:07:00 2018 : Debug: (1) Session-Timeout = 0

Tue Jul 10 18:07:00 2018 : Debug: (1) Event-Timestamp = "Jul 10 2018 18:07:12 MSK"

Tue Jul 10 18:07:00 2018 : Debug: (1) Acct-Status-Type = Start

Tue Jul 10 18:07:00 2018 : Debug: (1) Acct-Delay-Time = 2

Tue Jul 10 18:07:00 2018 : Debug: (1) Acct-Authentic = 0

Tue Jul 10 18:07:00 2018 : Debug: (1) Framed-IP-Address = 192.168.1.67

Tue Jul 10 18:07:00 2018 : Debug: (1) Framed-IPv6-Address = fe80::2499:faf8:246a:a9f3

Tue Jul 10 18:07:00 2018 : Debug: (1) Framed-IPv6-Address = fdd0:7ab5:af20:fb00:2499:faf8:246a:a9f3

Tue Jul 10 18:07:00 2018 : Debug: (1) Framed-IPv6-Address = fdd0:7ab5:af20:fb00:ac1a:6867:29ad:cf89

Tue Jul 10 18:07:00 2018 : Debug: (1) Connect-Info = "802.11a"

Tue Jul 10 18:07:00 2018 : Debug: (1) NAS-Port-Type = Wireless-Other

Tue Jul 10 18:07:00 2018 : Debug: (1) Called-Station-Id = "D88466272BF0"

Tue Jul 10 18:07:00 2018 : Debug: (1) Calling-Station-Id = "88B111C3EDFD"

Tue Jul 10 18:07:00 2018 : Debug: (1) NAS-IP-Address = 127.0.0.1

Tue Jul 10 18:07:00 2018 : Debug: (1) NAS-Identifier = "SupportVO"

Tue Jul 10 18:07:00 2018 : Debug: (1) Siemens-AP-Serial = "15141805085D0000"

Tue Jul 10 18:07:00 2018 : Debug: (1) Siemens-AP-Name = "15141805085D0000"

Tue Jul 10 18:07:00 2018 : Debug: (1) Siemens-BSS-MAC = "D88466272BF0"

Tue Jul 10 18:07:00 2018 : Debug: (1) Siemens-VNS-Name = "SupportVO"

Tue Jul 10 18:07:00 2018 : Debug: (1) Siemens-SSID = "SupportVO"

Tue Jul 10 18:07:00 2018 : Debug: (1) Siemens-Policy-Name = "Enterprise User"

Tue Jul 10 18:07:00 2018 : Debug: (1) Siemens-Topology-Name = "n/a"

Tue Jul 10 18:07:00 2018 : Debug: (1) # Executing section preacct from file /opt/nac/radius/raddb/sites-enabled/nac-server

Tue Jul 10 18:07:00 2018 : Debug: (1) preacct {

Tue Jul 10 18:07:00 2018 : Debug: (1) policy acct_unique {

Tue Jul 10 18:07:00 2018 : Debug: (1) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) {

Tue Jul 10 18:07:00 2018 : Debug: (1) EXPAND %{string:Class}

Tue Jul 10 18:07:00 2018 : Debug: (1) -->

Tue Jul 10 18:07:00 2018 : Debug: (1) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE

Tue Jul 10 18:07:00 2018 : Debug: (1) else {

Tue Jul 10 18:07:00 2018 : Debug: (1) update request {

Tue Jul 10 18:07:00 2018 : Debug: (1) EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}

Tue Jul 10 18:07:00 2018 : Debug: (1) --> 41b6e990b0fdd35070cde06e9ddf855a

Tue Jul 10 18:07:00 2018 : Debug: (1) Acct-Unique-Session-Id := 41b6e990b0fdd35070cde06e9ddf855a

Tue Jul 10 18:07:00 2018 : Debug: (1) } # update request = noop

Tue Jul 10 18:07:00 2018 : Debug: (1) } # else = noop

Tue Jul 10 18:07:00 2018 : Debug: (1) } # policy acct_unique = noop

Tue Jul 10 18:07:00 2018 : Debug: (1) modsingle[preacct]: calling etsnac (rlm_etsnac) for request 1

Tue Jul 10 18:07:00 2018 : Info: (1) [etsnac connection_mgr] AAA Request [ID: 1, Source IP: 192.168.1.111, Command: Accounting Request(0x06)]

(1) --- Request VPs ---

(1) Acct-Session-Id = "M3153457a0002"

(1) NAS-Port = 101

(1) User-Name = "88B111C3EDFD"

(1) Filter-Id = "Enterprise User"

(1) Acct-Interim-Interval = 1800

(1) Session-Timeout = 0

(1) Event-Timestamp = "Jul 10 2018 18:07:12 MSK"

(1) Acct-Status-Type = Start

(1) Acct-Delay-Time = 2

(1) Acct-Authentic = 0

(1) Framed-IP-Address = 192.168.1.67

(1) Framed-IPv6-Address = fe80::2499:faf8:246a:a9f3

(1) Framed-IPv6-Address = fdd0:7ab5:af20:fb00:2499:faf8:246a:a9f3

(1) Framed-IPv6-Address = fdd0:7ab5:af20:fb00:ac1a:6867:29ad:cf89

(1) Connect-Info = "802.11a"

(1) NAS-Port-Type = Wireless-Other

(1) Called-Station-Id = "D88466272BF0"

(1) Calling-Station-Id = "88B111C3EDFD"

(1) NAS-IP-Address = 127.0.0.1

(1) NAS-Identifier = "SupportVO"

(1) Siemens-AP-Serial = "15141805085D0000"

(1) Siemens-AP-Name = ****************

(1) Siemens-BSS-MAC = "D88466272BF0"

(1) Siemens-VNS-Name = "SupportVO"

(1) Siemens-SSID = "SupportVO"

(1) Siemens-Policy-Name = "Enterprise User"

(1) Siemens-Topology-Name = "n/a"

(1) Acct-Unique-Session-Id := "41b6e990b0fdd35070cde06e9ddf855a"

Tue Jul 10 18:07:00 2018 : Debug: [etsnac connection_mgr] Using loopback IP address to bind the client port to.

Tue Jul 10 18:07:00 2018 : Debug: [etsnac connection_mgr] Successfully connected to port: 1302 on server 127.0.0.1 from client port: 0

Tue Jul 10 18:07:00 2018 : Debug: (1) [etsnac connection_mgr] Using reconnected authentication server connection ID: 15.

Tue Jul 10 18:07:00 2018 : Info: (1) [etsnac connection_mgr] AAA Response [ID: 1, Command: Local Accounting Only(0x29)]

Tue Jul 10 18:07:00 2018 : Debug: (1) [etsnac connection_mgr] Releasing authentication server connection ID: 15.

Tue Jul 10 18:07:00 2018 : Debug: (1) [etsnac] The AAA server says to only process the accounting request locally.

Tue Jul 10 18:07:00 2018 : Debug: (1) modsingle[preacct]: returned from etsnac (rlm_etsnac) for request 1

Tue Jul 10 18:07:00 2018 : Debug: (1) [etsnac] = ok

Tue Jul 10 18:07:00 2018 : Debug: (1) } # preacct = ok

Tue Jul 10 18:07:00 2018 : Debug: (1) # Executing section accounting from file /opt/nac/radius/raddb/sites-enabled/nac-server

Tue Jul 10 18:07:00 2018 : Debug: (1) accounting {

Tue Jul 10 18:07:00 2018 : Debug: (1) modsingle[accounting]: calling etsnac (rlm_etsnac) for request 1

Tue Jul 10 18:07:00 2018 : Debug: (1) modsingle[accounting]: returned from etsnac (rlm_etsnac) for request 1

Tue Jul 10 18:07:00 2018 : Debug: (1) [etsnac] = ok

Tue Jul 10 18:07:00 2018 : Debug: (1) } # accounting = ok

Tue Jul 10 18:07:00 2018 : Debug: (1) Sent Accounting-Response Id 0 from 192.168.1.200:1813 to 192.168.1.111:49438 length 0

Tue Jul 10 18:07:00 2018 : Debug: (1) Finished request

Tue Jul 10 18:07:00 2018 : Debug: Thread 4 waiting to be assigned a request

Tue Jul 10 18:07:00 2018 : Debug: (1) Cleaning up request packet ID 0 with timestamp +177

Tue Jul 10 18:07:00 2018 : Info: Ready to process requests


Scroll to Top






This is for normal registration from iPhone:





Tue Jul 10 18:17:40 2018 : Debug: Waking up in 0.3 seconds.

Tue Jul 10 18:17:40 2018 : Debug: Thread 1 got semaphore

Tue Jul 10 18:17:40 2018 : Debug: Thread 1 handling request 2, (1 handled so far)

Tue Jul 10 18:17:40 2018 : Debug: (2) Received Access-Request Id 111 from 192.168.1.111:41745 to 192.168.1.200:1812 length 259

Tue Jul 10 18:17:40 2018 : Debug: (2) User-Name = "B48B197B521D"

Tue Jul 10 18:17:40 2018 : Debug: (2) User-Password = "B48B197B521D"

Tue Jul 10 18:17:40 2018 : Debug: (2) NAS-IP-Address = 127.0.0.1

Tue Jul 10 18:17:40 2018 : Debug: (2) NAS-Port = 101

Tue Jul 10 18:17:40 2018 : Debug: (2) NAS-Port-Type = Wireless-Other

Tue Jul 10 18:17:40 2018 : Debug: (2) NAS-Identifier = "SupportVO"

Tue Jul 10 18:17:40 2018 : Debug: (2) Siemens-AP-Serial = "15141805085D0000"

Tue Jul 10 18:17:40 2018 : Debug: (2) Siemens-AP-Name = "15141805085D0000"

Tue Jul 10 18:17:40 2018 : Debug: (2) Siemens-VNS-Name = "SupportVO"

Tue Jul 10 18:17:40 2018 : Debug: (2) Siemens-SSID = "SupportVO"

Tue Jul 10 18:17:40 2018 : Debug: (2) Siemens-BSS-MAC = "D88466272BF0"

Tue Jul 10 18:17:40 2018 : Debug: (2) Siemens-Policy-Name = "Non Authenticated"

Tue Jul 10 18:17:40 2018 : Debug: (2) Calling-Station-Id = "B48B197B521D"

Tue Jul 10 18:17:40 2018 : Debug: (2) Called-Station-Id = "D88466272BF0"

Tue Jul 10 18:17:40 2018 : Debug: (2) Acct-Session-Id = "M315475b30003"

Tue Jul 10 18:17:40 2018 : Debug: (2) session-state: No State attribute

Tue Jul 10 18:17:40 2018 : Debug: (2) # Executing section authorize from file /opt/nac/radius/raddb/sites-enabled/nac-server

Tue Jul 10 18:17:40 2018 : Debug: (2) authorize {

Tue Jul 10 18:17:40 2018 : Debug: (2) update control {

Tue Jul 10 18:17:40 2018 : Debug: (2) EXPAND %{Calling-Station-Id}

Tue Jul 10 18:17:40 2018 : Debug: (2) --> B48B197B521D

Tue Jul 10 18:17:40 2018 : Debug: (2) Load-Balance-Key = B48B197B521D

Tue Jul 10 18:17:40 2018 : Debug: (2) } # update control = noop

Tue Jul 10 18:17:40 2018 : Debug: (2) modsingle[authorize]: calling etsnac (rlm_etsnac) for request 2

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac] *NOT* Continuing proxied conversation, skipping...

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac nac_request_mgr] Generated MAC b48b197b521d from Calling-Station-Id: B48B197B521D

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac nac_request_mgr] Found username from: User-Name: B48B197B521D

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac nac_request_mgr] Found User-Password attribute: 2, setting auth type to: PAP

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac nac_request_mgr] Found switch ip from: NAS-IP-Address: 127.0.0.1

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac nac_request_mgr] Unable to find existing NAC request manager instance.

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac nac_request_mgr] Making a new request to the AAA server for request ID: 2

Tue Jul 10 18:17:40 2018 : Info: (2) [etsnac connection_mgr] AAA Request [ID: 2, Source IP: 192.168.1.111, Command: Authenticate & Authorize Request(0x02)]

(2) --- Request VPs ---

(2) User-Name = "B48B197B521D"

(2) User-Password = ************

(2) NAS-IP-Address = 127.0.0.1

(2) NAS-Port = 101

(2) NAS-Port-Type = Wireless-Other

(2) NAS-Identifier = "SupportVO"

(2) Siemens-AP-Serial = "15141805085D0000"

(2) Siemens-AP-Name = ****************

(2) Siemens-VNS-Name = "SupportVO"

(2) Siemens-SSID = "SupportVO"

(2) Siemens-BSS-MAC = "D88466272BF0"

(2) Siemens-Policy-Name = "Non Authenticated"

(2) Calling-Station-Id = "B48B197B521D"

(2) Called-Station-Id = "D88466272BF0"

(2) Acct-Session-Id = "M315475b30003"

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac connection_mgr] Using authentication server connection ID: 31.

Tue Jul 10 18:17:40 2018 : Info: (2) [etsnac connection_mgr] AAA Response [ID: 2, Command: Accept User(0x22)]

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac connection_mgr] Releasing authentication server connection ID: 31.

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac nac_request_mgr] Unable to find existing NAC request manager instance.

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac] The AAA server says to accept the request.

Tue Jul 10 18:17:40 2018 : Debug: (2) modsingle[authorize]: returned from etsnac (rlm_etsnac) for request 2

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac] = ok

Tue Jul 10 18:17:40 2018 : Debug: (2) modsingle[authorize]: calling chap (rlm_chap) for request 2

Tue Jul 10 18:17:40 2018 : Debug: (2) modsingle[authorize]: returned from chap (rlm_chap) for request 2

Tue Jul 10 18:17:40 2018 : Debug: (2) [chap] = noop

Tue Jul 10 18:17:40 2018 : Debug: (2) modsingle[authorize]: calling mschap (rlm_mschap) for request 2

Tue Jul 10 18:17:40 2018 : Debug: (2) modsingle[authorize]: returned from mschap (rlm_mschap) for request 2

Tue Jul 10 18:17:40 2018 : Debug: (2) [mschap] = noop

Tue Jul 10 18:17:40 2018 : Debug: (2) modsingle[authorize]: calling eap (rlm_eap) for request 2

Tue Jul 10 18:17:40 2018 : Debug: (2) eap: No EAP-Message, not doing EAP

Tue Jul 10 18:17:40 2018 : Debug: (2) modsingle[authorize]: returned from eap (rlm_eap) for request 2

Tue Jul 10 18:17:40 2018 : Debug: (2) [eap] = noop

Tue Jul 10 18:17:40 2018 : Debug: (2) modsingle[authorize]: calling pap (rlm_pap) for request 2

Tue Jul 10 18:17:40 2018 : WARNING: (2) pap: Auth-Type already set. Not setting to PAP

Tue Jul 10 18:17:40 2018 : Debug: (2) modsingle[authorize]: returned from pap (rlm_pap) for request 2

Tue Jul 10 18:17:40 2018 : Debug: (2) [pap] = noop

Tue Jul 10 18:17:40 2018 : Debug: (2) } # authorize = ok

Tue Jul 10 18:17:40 2018 : Debug: (2) Found Auth-Type = Accept

Tue Jul 10 18:17:40 2018 : Debug: (2) Auth-Type = Accept, accepting the user

Tue Jul 10 18:17:40 2018 : Debug: (2) # Executing section post-auth from file /opt/nac/radius/raddb/sites-enabled/nac-server

Tue Jul 10 18:17:40 2018 : Debug: (2) post-auth {

Tue Jul 10 18:17:40 2018 : Debug: (2) modsingle[post-auth]: calling etsnac (rlm_etsnac) for request 2

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac] Processing Response-Packet-Type Access-Accept(2)

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac] Not running EAP-TLS User-Name replacement for non EAP authentication

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac nac_request_mgr] Generated MAC b48b197b521d from Calling-Station-Id: B48B197B521D

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac nac_request_mgr] Found username from: User-Name: B48B197B521D

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac nac_request_mgr] Found User-Password attribute: 2, setting auth type to: PAP

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac nac_request_mgr] Found switch ip from: NAS-IP-Address: 127.0.0.1

Tue Jul 10 18:17:40 2018 : Info: (2) [etsnac connection_mgr] AAA Request [ID: 2, Source IP: 192.168.1.111, Command: Post Authorize Request(0x03)]

(2) --- Request VPs ---

(2) User-Name = "B48B197B521D"

(2) User-Password = ************

(2) NAS-IP-Address = 127.0.0.1

(2) NAS-Port = 101

(2) NAS-Port-Type = Wireless-Other

(2) NAS-Identifier = "SupportVO"

(2) Siemens-AP-Serial = "15141805085D0000"

(2) Siemens-AP-Name = ****************

(2) Siemens-VNS-Name = "SupportVO"

(2) Siemens-SSID = "SupportVO"

(2) Siemens-BSS-MAC = "D88466272BF0"

(2) Siemens-Policy-Name = "Non Authenticated"

(2) Calling-Station-Id = "B48B197B521D"

(2) Called-Station-Id = "D88466272BF0"

(2) Acct-Session-Id = "M315475b30003"

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac connection_mgr] Using authentication server connection ID: 31.

Tue Jul 10 18:17:40 2018 : Info: (2) [etsnac connection_mgr] AAA Response [ID: 2, Command: Replace Response Attributes(0x27)]

(2) Filter-Id := "Enterasys:version=1:policy=Unregistered"

(2) Login-LAT-Port := "0"

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac connection_mgr] Releasing authentication server connection ID: 31.

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac] The AAA server says to replace the response attributes.

Tue Jul 10 18:17:40 2018 : Debug: (2) modsingle[post-auth]: returned from etsnac (rlm_etsnac) for request 2

Tue Jul 10 18:17:40 2018 : Debug: (2) [etsnac] = updated

Tue Jul 10 18:17:40 2018 : Debug: (2) } # post-auth = updated

Tue Jul 10 18:17:40 2018 : Debug: (2) Sent Access-Accept Id 111 from 192.168.1.200:1812 to 192.168.1.111:41745 length 0

Tue Jul 10 18:17:40 2018 : Debug: (2) Filter-Id := "Enterasys:version=1:policy=Unregistered"

Tue Jul 10 18:17:40 2018 : Debug: (2) Login-LAT-Port := "0"

Tue Jul 10 18:17:40 2018 : Debug: (2) Finished request

Tue Jul 10 18:17:40 2018 : Debug: Thread 1 waiting to be assigned a request

Tue Jul 10 18:17:40 2018 : Debug: Waking up in 4.7 seconds.

Tue Jul 10 18:17:45 2018 : Debug: (2) Cleaning up request packet ID 111 with timestamp +817

Tue Jul 10 18:17:45 2018 : Info: Ready to process requests

Tue Jul 10 18:18:14 2018 : Debug: Waking up in 0.3 seconds.

Tue Jul 10 18:18:14 2018 : Debug: Thread 2 got semaphore

Tue Jul 10 18:18:14 2018 : Debug: Thread 2 handling request 3, (1 handled so far)

Tue Jul 10 18:18:14 2018 : Debug: (3) Received Accounting-Request Id 1 from 192.168.1.111:49438 to 192.168.1.200:1813 length 366

Tue Jul 10 18:18:14 2018 : Debug: (3) Acct-Session-Id = "M315475b30003"

Tue Jul 10 18:18:14 2018 : Debug: (3) NAS-Port = 101

Tue Jul 10 18:18:14 2018 : Debug: (3) User-Name = "B48B197B521D"

Tue Jul 10 18:18:14 2018 : Debug: (3) Filter-Id = "Enterprise User"

Tue Jul 10 18:18:14 2018 : Debug: (3) Acct-Interim-Interval = 1800

Tue Jul 10 18:18:14 2018 : Debug: (3) Session-Timeout = 0

Tue Jul 10 18:18:14 2018 : Debug: (3) Event-Timestamp = "Jul 10 2018 18:18:25 MSK"

Tue Jul 10 18:18:14 2018 : Debug: (3) Acct-Status-Type = Start

Tue Jul 10 18:18:14 2018 : Debug: (3) Acct-Delay-Time = 0

Tue Jul 10 18:18:14 2018 : Debug: (3) Acct-Authentic = 0

Tue Jul 10 18:18:14 2018 : Debug: (3) Framed-IP-Address = 192.168.1.62

Tue Jul 10 18:18:14 2018 : Debug: (3) Framed-IPv6-Address = fe80::106a:5575:f8d5:bc1d

Tue Jul 10 18:18:14 2018 : Debug: (3) Framed-IPv6-Address = fdd0:7ab5:af20:fb00:1c96:8f7f:4546:8d86

Tue Jul 10 18:18:14 2018 : Debug: (3) Framed-IPv6-Address = fdd0:7ab5:af20:fb00:9d4a:e9be:5ab8:1935

Tue Jul 10 18:18:14 2018 : Debug: (3) Connect-Info = "802.11b/g"

Tue Jul 10 18:18:14 2018 : Debug: (3) NAS-Port-Type = Wireless-Other

Tue Jul 10 18:18:14 2018 : Debug: (3) Called-Station-Id = "D88466272BF0"

Tue Jul 10 18:18:14 2018 : Debug: (3) Calling-Station-Id = "B48B197B521D"

Tue Jul 10 18:18:14 2018 : Debug: (3) NAS-IP-Address = 127.0.0.1

Tue Jul 10 18:18:14 2018 : Debug: (3) NAS-Identifier = "SupportVO"

Tue Jul 10 18:18:14 2018 : Debug: (3) Siemens-AP-Serial = "15141805085D0000"

Tue Jul 10 18:18:14 2018 : Debug: (3) Siemens-AP-Name = "15141805085D0000"

Tue Jul 10 18:18:14 2018 : Debug: (3) Siemens-BSS-MAC = "D88466272BF0"

Tue Jul 10 18:18:14 2018 : Debug: (3) Siemens-VNS-Name = "SupportVO"

Tue Jul 10 18:18:14 2018 : Debug: (3) Siemens-SSID = "SupportVO"

Tue Jul 10 18:18:14 2018 : Debug: (3) Siemens-Policy-Name = "Enterprise User"

Tue Jul 10 18:18:14 2018 : Debug: (3) Siemens-Topology-Name = "n/a"

Tue Jul 10 18:18:14 2018 : Debug: (3) # Executing section preacct from file /opt/nac/radius/raddb/sites-enabled/nac-server

Tue Jul 10 18:18:14 2018 : Debug: (3) preacct {

Tue Jul 10 18:18:14 2018 : Debug: (3) policy acct_unique {

Tue Jul 10 18:18:14 2018 : Debug: (3) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) {

Tue Jul 10 18:18:14 2018 : Debug: (3) EXPAND %{string:Class}

Tue Jul 10 18:18:14 2018 : Debug: (3) -->

Tue Jul 10 18:18:14 2018 : Debug: (3) if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE

Tue Jul 10 18:18:14 2018 : Debug: (3) else {

Tue Jul 10 18:18:14 2018 : Debug: (3) update request {

Tue Jul 10 18:18:14 2018 : Debug: (3) EXPAND %{md5:%{User-Name},%{Acct-Session-ID},%{%{NAS-IPv6-Address}:-%{NAS-IP-Address}},%{NAS-Identifier},%{NAS-Port-ID},%{NAS-Port}}

Tue Jul 10 18:18:14 2018 : Debug: (3) --> b077e2f74544092fc304c5651d34916b

Tue Jul 10 18:18:14 2018 : Debug: (3) Acct-Unique-Session-Id := b077e2f74544092fc304c5651d34916b

Tue Jul 10 18:18:14 2018 : Debug: (3) } # update request = noop

Tue Jul 10 18:18:14 2018 : Debug: (3) } # else = noop

Tue Jul 10 18:18:14 2018 : Debug: (3) } # policy acct_unique = noop

Tue Jul 10 18:18:14 2018 : Debug: (3) modsingle[preacct]: calling etsnac (rlm_etsnac) for request 3

Tue Jul 10 18:18:14 2018 : Info: (3) [etsnac connection_mgr] AAA Request [ID: 3, Source IP: 192.168.1.111, Command: Accounting Request(0x06)]

(3) --- Request VPs ---

(3) Acct-Session-Id = "M315475b30003"

(3) NAS-Port = 101

(3) User-Name = "B48B197B521D"

(3) Filter-Id = "Enterprise User"

(3) Acct-Interim-Interval = 1800

(3) Session-Timeout = 0

(3) Event-Timestamp = "Jul 10 2018 18:18:25 MSK"

(3) Acct-Status-Type = Start

(3) Acct-Delay-Time = 0

(3) Acct-Authentic = 0

(3) Framed-IP-Address = 192.168.1.62

(3) Framed-IPv6-Address = fe80::106a:5575:f8d5:bc1d

(3) Framed-IPv6-Address = fdd0:7ab5:af20:fb00:1c96:8f7f:4546:8d86

(3) Framed-IPv6-Address = fdd0:7ab5:af20:fb00:9d4a:e9be:5ab8:1935

(3) Connect-Info = "802.11b/g"

(3) NAS-Port-Type = Wireless-Other

(3) Called-Station-Id = "D88466272BF0"

(3) Calling-Station-Id = "B48B197B521D"

(3) NAS-IP-Address = 127.0.0.1

(3) NAS-Identifier = "SupportVO"

(3) Siemens-AP-Serial = "15141805085D0000"

(3) Siemens-AP-Name = ****************

(3) Siemens-BSS-MAC = "D88466272BF0"

(3) Siemens-VNS-Name = "SupportVO"

(3) Siemens-SSID = "SupportVO"

(3) Siemens-Policy-Name = "Enterprise User"

(3) Siemens-Topology-Name = "n/a"

(3) Acct-Unique-Session-Id := "b077e2f74544092fc304c5651d34916b"

Tue Jul 10 18:18:14 2018 : Debug: (3) [etsnac connection_mgr] Using authentication server connection ID: 15.

Tue Jul 10 18:18:14 2018 : Info: (3) [etsnac connection_mgr] AAA Response [ID: 3, Command: Local Accounting Only(0x29)]

Tue Jul 10 18:18:14 2018 : Debug: (3) [etsnac connection_mgr] Releasing authentication server connection ID: 15.

Tue Jul 10 18:18:14 2018 : Debug: (3) [etsnac] The AAA server says to only process the accounting request locally.

Tue Jul 10 18:18:14 2018 : Debug: (3) modsingle[preacct]: returned from etsnac (rlm_etsnac) for request 3

Tue Jul 10 18:18:14 2018 : Debug: (3) [etsnac] = ok

Tue Jul 10 18:18:14 2018 : Debug: (3) } # preacct = ok

Tue Jul 10 18:18:14 2018 : Debug: (3) # Executing section accounting from file /opt/nac/radius/raddb/sites-enabled/nac-server

Tue Jul 10 18:18:14 2018 : Debug: (3) accounting {

Tue Jul 10 18:18:14 2018 : Debug: (3) modsingle[accounting]: calling etsnac (rlm_etsnac) for request 3

Tue Jul 10 18:18:14 2018 : Debug: (3) modsingle[accounting]: returned from etsnac (rlm_etsnac) for request 3

Tue Jul 10 18:18:14 2018 : Debug: (3) [etsnac] = ok

Tue Jul 10 18:18:14 2018 : Debug: (3) } # accounting = ok

Tue Jul 10 18:18:14 2018 : Debug: (3) Sent Accounting-Response Id 1 from 192.168.1.200:1813 to 192.168.1.111:49438 length 0

Tue Jul 10 18:18:14 2018 : Debug: (3) Finished request

Tue Jul 10 18:18:14 2018 : Debug: Thread 2 waiting to be assigned a request

Tue Jul 10 18:18:14 2018 : Debug: (3) Cleaning up request packet ID 1 with timestamp +851

Tue Jul 10 18:18:14 2018 : Info: Ready to process requests

Photo of Ilya Semenov

Ilya Semenov

  • 4,610 Points 4k badge 2x thumb

Posted 3 months ago

  • 0
  • 1
Photo of SH

SH

  • 4,204 Points 4k badge 2x thumb
Hello Ilya,

first of all according my experience IPhones have to reach the Gateway during DHCP, if not there are problems while getting the ipaddress. If the Gateway communicated in the DHCP offer is not present in the network the DORA process is completed but the IPhone will not use the ip address.

For your problem 2 (endless registration): Maybe this screws will help:
https://gtacknowledge.extremenetworks.com/articles/How_To/How-to-decrease-delay-between-Registration...

Best regards
Stephan
Photo of Yacobucci, Ryan

Yacobucci, Ryan, Multi-Tier Technical Support Engineer

  • 5,354 Points 5k badge 2x thumb
Hello,

1. Extreme Management Center --> wireless --> clients will provide information that was obtained from the Controller. Unless the controller has a client that is doing 802.1x, which provides the username within the authentication protocol, you will not see the username here. 

The captive portal is held on the NAC appliance and this information will be seen in the Control --> End Systems tab, but the EWC does not have any knowledge that the client has been through a captive protal, does not know what credentials have been provided, so it cannot display them.


2. What version of iOS? Are all version affected?

3. As far as "Endless registration" is concerned, check the Control captive portal options and see what the redirection configurations are set to. Are they set to  use the users requested URL?

The workflow should be the following: 

User puts in credentials and hits register
Browser is set to send requests to the NAC waiting for a message to tell it to proceed
When the client has been registered NAC will respond with a transition.jsp script to indicate to the client that they should move on to the next page. 

If the client doesn't have connectivity to NAC in the role that has been provided by registration then the client will never receive the instruction to transition. 


Try setting the "redirect immediately" option in the captive portal option. This will have the client test to internet connectivity to trigger the transition rather than wait for the NAC. 



4. You have provided freeRADIUS debug, we'll need different debug to see what's going on.
Enable debug for Captive portal in the debug screen and send in the tag.log

Captive Portal --> Display
Captive Portal --> Registration and Remediation

Thanks
-Ryan
Photo of Ilya Semenov

Ilya Semenov

  • 4,610 Points 4k badge 2x thumb
Hello, Ryan,

many thanks for your response. Could you please enlight me in some details?

1. Are there any ways to implement authentication using NAC where I will be see AD's UserName in XMC Wireless>Clients? What should be configured? Now I have:

 

and...





2. I've test just my own Iphone6 with iOS 11.3. Tomorrow I'll test some other apples.

3. OK, I've set "redirect immideately" - I'll check it tomorrow too.



4. I've provided debug from NAC's admin page log. I do not use freeradius. Also, I've not found how to do this:

"Enable debug for Captive portal in the debug screen and send in the tag.log

Captive Portal --> Display
Captive Portal --> Registration and Remediation"


I've this enabled:





Ryan, I willingly send any part of my conf if it could clear the situation. Many thanks to you!
Photo of Yacobucci, Ryan

Yacobucci, Ryan, Multi-Tier Technical Support Engineer

  • 5,354 Points 5k badge 2x thumb
Hello,

1. If you changed the WLAN service mode to be 802.1x you will be able to see the username in the XMC Wireless --> Clients section. 

This will cause a fundamental change in authentication requiring the end systems to complete 802.1x authentication. This is likely not a configuration change you want to make as you have a captive portal configuration.

You can configured 802.1x and captive portal at the same time, but this causes the client to have to login twice in order to get on the network, which is redundant.

2 --> waiting for results

3 --> waiting for results

4. Enable debug for:
Captive Portal - Display
Captive Portal - Registration and Remediation

Authentication Request Processing - NAC


Once you enable the debug delete the client and attempt to register.

Once you have completed the test disable the diagnostics and send in the /var/log/tag.log and export the end system events. 

I would suggest a GTAC case for this :)

Thanks
-Ryan
Photo of Ilya Semenov

Ilya Semenov

  • 4,610 Points 4k badge 2x thumb
Hello, Ryan,

a Kind Man has consulted me today - it's seems that there was kind of misunderstanding. 

Usernames have appeared in NAC>End-Systems, but have not appeared in Wireless>Clients - and it is expected behavior. That is sad.

So, the only thing remains to correct is the Endless registration on Windows 10 laptops. Tomorrow I'll check this issue with different Windows versions.

Thanks for your help!
Photo of Pala, Zdenek

Pala, Zdenek, Employee

  • 9,620 Points 5k badge 2x thumb
Hi

another reason for the described behavior can be short DHCP lease time or the user roams from one AP to another. Is the client stable on the wireless AP or it does roam and roam and roam?
Photo of Ilya Semenov

Ilya Semenov

  • 4,610 Points 4k badge 2x thumb
Clients are stable, Zdenek. Thanks.