Información sobre Debug Client en Wireless LAN Controllers (WLC)

Introducción

En este documento se describe información detallada sobre debug client en los controladores de LAN inalámbrica (WLC).

Prerequisites

Requirements

En este documento se tratan los siguientes temas:

• Cómo se gestiona un cliente inalámbrico
• Cómo solucionar problemas de asociación y autenticación básicas

El resultado que se analizará cubre el escenario de una red WPA con clave precompartida (WPA-PSK).

Cisco recomienda que tenga conocimiento sobre estos temas:

• Cómo configurar el WLC y el Lightweight Access Point (LAP) para el funcionamiento básico
• Protocolo ligero de punto de acceso (LWAPP) y métodos de seguridad inalámbrica
• Cómo funcionan los procesos de autenticación y asociación 802.11

Componentes Utilizados

La información que contiene este documento se basa en las siguientes versiones de software y hardware.

• WLC de Cisco AireOS (8540, 5520, vWLC) que ejecuta firmware 8.5 u 8.10.
• Puntos de acceso basados en CAPWAP.

La información que contiene este documento se creó a partir de los dispositivos en un ambiente de laboratorio específico. Todos los dispositivos que se utilizan en este documento se pusieron en funcionamiento con una configuración verificada (predeterminada). Si tiene una red en vivo, asegúrese de entender el posible impacto de cualquier comando.

Convenciones

Consulte Convenciones de Consejos TécnicosCisco para obtener más información sobre las convenciones del documento.

Cliente de depuración

El comando debug client es una macro que habilita ocho comandos debug, más un filtro en la dirección MAC proporcionada, de modo que sólo se muestran los mensajes que contienen la dirección MAC especificada. Los ocho comandos debug muestran los detalles más importantes sobre la asociación y autenticación de clientes. El filtro ayuda en situaciones en las que hay varios clientes inalámbricos. Situaciones como cuando se genera demasiada salida o cuando el controlador se sobrecarga cuando se habilita el debug sin el filtro.

La información recopilada abarca detalles importantes sobre la asociación y autenticación de clientes (con dos excepciones que se mencionan más adelante en este documento).

Los comandos que están habilitados se muestran en este resultado:

(Cisco Controller) >show debug
 
MAC address ................................ 00:00:00:00:00:00
 
Debug Flags Enabled:
  dhcp packet enabled.
  dot11 mobile enabled.
  dot11 state enabled.
  dot1x events enabled.
  dot1x states enabled.
  pem events enabled.
  pem state enabled.

Estos comandos abarcan la negociación de direcciones, la máquina de estado de cliente 802.11, la autenticación 802.1x, el módulo de aplicación de políticas (PEM) y la negociación de direcciones (DHCP).

Depurar variaciones de cliente

En la mayoría de los escenarios, debug client es suficiente para obtener la información necesaria. Sin embargo, hay dos situaciones importantes en las que se necesita una depuración adicional:

• Movilidad (itinerancia del cliente entre controladores)
• Solucionar problemas de autenticación EAP

Movilidad

En esta situación, las depuraciones de movilidad deben habilitarse después de la debug client se ha introducido el comando para obtener información adicional sobre la interacción del protocolo de movilidad entre los controladores.

Nota: Los detalles de esta salida se tratan en otros documentos.

Para habilitar los debugs de movilidad, utilice el debug client y, a continuación, utilice el comando debug mobility handoff enable comando:

(Cisco Controller) >debug client 00:00:00:00:00:00
 
(Cisco Controller) >debug mobility handoff enable 

(Cisco Controller) >show debug

MAC address ................................ 00:00:00:00:00:00

Debug Flags Enabled:
  dhcp packet enabled.
  dot11 mobile enabled.
  dot11 state enabled
  dot1x events enabled.
  dot1x states enabled.
  mobility handoff enabled.
  pem events enabled.
  pem state enabled.

Solucionar problemas de autenticación EAP

Para resolver problemas de interacción entre el WLC y el servidor de autenticación (RADIUS externo o servidor EAP interno), utilice el debug AAA all enable , que muestra los detalles necesarios. Este comando se utiliza después de la debug client y se puede combinar con otros comandos debug según sea necesario (por ejemplo, el comando handoff ).

(Cisco Controller) >debug client 00:00:00:00:00:00
(Cisco Controller) >debug aaa all enable 
(Cisco Controller) >show debug
MAC address ................................ 00:00:00:00:00:00
Debug Flags Enabled:
  aaa detail enabled.
  aaa events enabled.
  aaa packet enabled.
  aaa packet enabled.
  aaa ldap enabled.
  aaa local-auth db enabled.
  aaa local-auth eap framework errors enabled.
  aaa local-auth eap framework events enabled.
  aaa local-auth eap framework packets enabled.
  aaa local-auth eap framework state machine enabled.
  aaa local-auth eap method errors enabled.
  aaa local-auth eap method events enabled.
  aaa local-auth eap method packets enabled.
  aaa local-auth eap method state machine enabled.
  aaa local-auth shim enabled.
  aaa tacacs enabled.
  dhcp packet enabled.
  dot11 mobile enabled.
  dot11 state enabled
  dot1x events enabled
  dot1x states enabled.
  mobility handoff enabled.
  pem events enabled.
  pem state enabled.

Conexión del cliente

A los efectos de este documento, conexión del cliente es el proceso para que un cliente inalámbrico pase a través de estos pasos:

Sección 802.11

1. Sondeo, para encontrar un AP válido para asociar.
2. Autenticación: puede ser abierta (nula) o compartida. Normalmente, se selecciona Abrir.
3. Asociación: Solicitar servicios de datos al AP.

Sección Políticas L2

1. Ninguno; la autenticación PSK o EAP se realiza en función de la configuración.
2. Negociación de claves, si se selecciona un método de cifrado.

Sección Políticas L3

1. Aprendizaje de la dirección.
2. Autenticación web, si está seleccionada.

Nota: Estos pasos representan un subconjunto o resumen del proceso completo. Este documento describe un escenario simplificado que cubre las políticas 802.11 y L2 y utiliza WPA-PSK, además del aprendizaje de direcciones. No se utilizan políticas AAA o L3 externas para la autenticación.

Procesos del controlador

En cada sección, el controlador utiliza procesos separados para realizar un seguimiento del estado del cliente en cada momento. Los procesos interactúan entre ellos para garantizar que el cliente se agrega a la tabla de conexión (según las políticas de seguridad configuradas). Para comprender los pasos de conexión del cliente con el controlador, aquí hay un breve resumen de los procesos más relevantes:

• Módulo de aplicación de políticas (PEM) : controla el estado del cliente y lo fuerza a través de cada una de las políticas de seguridad de la configuración WLAN.
• Access Point Functions (APF) — Básicamente, la máquina de estado 802.11.
• Dot1x: implementa la máquina de estado para 802.1x , la autenticación PSK y el identificador de clave para los clientes inalámbricos.
• Movilidad: realiza un seguimiento de la interacción con otros controladores del mismo grupo de movilidad.
• Capa de transformación de datos (DTL) : se sitúa entre los componentes de software y la aceleración de hardware de red (NPU); controla la información ARP.

Módulo de aplicación de políticas (PEM)

Según la configuración de WLAN, el cliente pasa por una serie de pasos. PEM garantiza que esto se realiza para que cumpla con las políticas de seguridad L2 y L3 requeridas.

Este es un subconjunto de los estados PEM relevantes para el análisis de una depuración de cliente:

• START: estado inicial de la nueva entrada de cliente.
• AUTHCHECK: WLAN tiene una política de autenticación L2 para aplicar.
• 8021X_REQD: el cliente debe completar la autenticación 802.1x.
• L2AUTHCOMPLETE: el cliente ha finalizado correctamente la política L2. El proceso ahora puede continuar con las políticas L3 (aprendizaje de direcciones, autenticación Web, etc.). El controlador envía aquí el anuncio de movilidad para obtener información de nivel 3 de otros controladores si se trata de un cliente que se desplaza en el mismo grupo de movilidad.
• WEP_REQD: el cliente debe completar la autenticación WEP.
• DHCP_REQD: El controlador necesita aprender la dirección L3 del cliente, lo cual se hace por solicitud ARP, solicitud DHCP o renovación, o por información aprendida de otro controlador en el grupo de movilidad. Si DHCP Required está marcado en el WLAN, sólo se utiliza la información de movilidad o DHCP.
• WEBAUTH_REQD: el cliente debe completar la autenticación Web. (política L3)
• RUN: el cliente ha completado correctamente las políticas L2 y L3 necesarias y ahora puede transmitir tráfico a la red.

Esta imagen muestra una máquina de estado PEM simplificada con las transiciones del cliente hasta que alcanza el estado RUN, donde el cliente ahora puede enviar tráfico a la red:

Nota: Esta figura no cubre todas las transiciones y estados posibles. Algunos pasos intermedios se han eliminado para mayor claridad.

Reenvío de tráfico de cliente

Entre el estado START y antes del estado RUN final, el tráfico del cliente no se reenvía a la red, sino que se pasa a la CPU principal en el controlador para su análisis. La información que se reenvía depende del estado y de las políticas en vigor; por ejemplo, si 802.1x está habilitado, el tráfico EAPOL se reenvía a la CPU. Otro ejemplo es que si se utiliza Web Auth, la CPU permite y intercepta HTTP y DNS para realizar la redirección web y obtener las credenciales de autenticación de cliente.

Cuando el cliente alcanza el estado RUN, la información del cliente se envía a la NPU para habilitar la conmutación FastPath, que realiza un reenvío a velocidad de cable del tráfico del usuario a la VLAN del cliente y libera a la CPU central de las tareas de reenvío de datos del usuario.

El tráfico que se reenvía depende del tipo de cliente que se aplica a la NPU. En esta tabla se describen los tipos más relevantes:

Tipo	Descripción
1	Reenvío de tráfico de cliente normal.
9	Estado de aprendizaje de IP. Un paquete de este cliente se envía a la CPU para aprender la dirección IP utilizada.
2	Transferencia de ACL. Se utiliza cuando la WLAN es una ACL configurada para informar a la NPU.

Funciones de punto de acceso (APF)

Este proceso maneja el estado del cliente a través del estado de la máquina 802.11 e interactúa con el código de movilidad para validar los diferentes escenarios de roaming. Este documento no cubre los detalles de la movilidad ni sus estados.

Esta tabla muestra los estados de cliente más relevantes que pueden ocurrir cuando un cliente está asociado al controlador:

Nombre	Descripción
Inactivo	Nuevo cliente o estado temporal en algunas situaciones.
Colgante AAA	El cliente espera la autenticación de la dirección MAC.
Autenticado	En algunas situaciones, la autenticación abierta se realiza correctamente o tiene un estado intermedio.
Asociado	El cliente pasó correctamente los procesos de autenticación MAC y de autenticación abierta.
Desasociado	El cliente envió la desasociación/desautenticación o el temporizador de asociación expiró.
Para eliminar	Cliente marcado para ser eliminado (normalmente después de que caducara el temporizador de exclusión).
Sondeo	Solicitud de sondeo recibida para el nuevo cliente.
Excluido/Bloqueado enumerado	El cliente se ha marcado como excluido. Normalmente relacionado con políticas WPS.
No válido	Error en el estado del cliente.

Esta imagen representa una transición de máquina de estado y muestra solamente los estados y transiciones más relevantes:

Autenticación 802.1x (Dot1x)

El proceso Dot1x es responsable de la autenticación 802.1x y de la administración de claves para el cliente. Esto significa que, incluso en las WLAN que no tienen una política EAP que requiera 802.1x, dot1x participa para manejar la creación y negociación de claves con el cliente y también para el manejo de claves en caché (PMK o CCKM).

Esta máquina de estado muestra las transiciones completas de 802.1x:

Análisis de depuración del cliente

Esta sección muestra el proceso completo en los registros cuando un cliente se conecta a una WLAN.

APF Process

Wed Oct 31 10:46:13 2007: 00:1b:77:42:07:69 Adding mobile on LWAPP AP 
    00:1c:0j:ca:5f:c0(0) 

!--- A new station is received. After validating type, it is added to the 
!--- AP that received it. This can happen both on processing association 
!--- request or probe requests


Wed Oct 31 10:46:13 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 23) in 5 seconds

!--- Sets an expiration timer for this entry in case it does not progress 
!--- beyond probe status. 5 Seconds corresponds to Probe Timeout. This message 
!--- might appear with other time values since, during client processing, 
!--- other functions might set different timeouts that depend on state.


Wed Oct 31 10:46:13 2007: 00:1b:77:42:07:69 apfProcessProbeReq 
    (apf_80211.c:4057) Changing state for mobile 00:1b:77:42:07:69 on AP 
    00:1c:0j:ca:5f:c0 from Idle to Probe

!--- APF state machine is updated.


Wed Oct 31 10:46:13 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds

!--- New Probe request update sent AP about client. IMPORTANT: 
!--- Access points do not forward all probe requests to the controller; they 
!--- summarize per time interval (by default 500 msec). This information is 
!--- used later by location and load balancing processes.


Wed Oct 31 10:46:14 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds

!--- New Probe request update sent AP about client.


Wed Oct 31 10:46:14 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds

!--- New Probe request update sent AP about client.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds

!--- New Probe request update sent AP about client.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Association received from 
    mobile on AP 00:1c:0j:ca:5f:c0

!--- Access point reports an association request from the client. 
!--- When the process reaches this point, the client is not excluded and not 
!--- in mobility intermediate state


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 STA - rates (8): 140 18 152 
    36 176 72 96 108 0 0 0 0 0 0 0 0

!--- Controller saves the client supported rates into its connection table. 
!--- Units are values of 500 kbps, basic (mandatory) rates have the Most Significant bit (MSb) set. 
!--- The above would be 6mbps basic, 9, 12 basic, 18, 24 basic, 36, 48, 54


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Processing WPA IE type 221, 
    length 24 for mobile 00:1b:77:42:07:69

!--- Controller validates the 802.11i security information element.



PEM Process


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 START (0) Deleted mobile 
    LWAPP rule on AP [00:1c:0j:ca:5f:c0]

!--- As the client requests new association, APF requests to PEM to delete the 
!--- client state and remove any traffic forwarding rules that it could have.



APF Process


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Updated location for station old 
    AP 00:00:00:00:00:00-0, new AP 00:1c:0j:ca:5f:c0-1

!--- APF updates where this client is located. For example, this client is 
!--- a new addition; therefore, no value exists for the old location.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 START (0) Initializing 
    policy

!--- PEM notifies that this is a new user. Security policies are checked 
!--- for enforcement.



PEM Process


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 START (0) Change state 
    to AUTHCHECK (2) last state AUTHCHECK (2)

!--- PEM marks as authentication check needed.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 AUTHCHECK (2) Change 
    state to 8021X_REQD (3) last state 8021X_REQD 

!--- After the WLAN configuration is checked, the client will need either 
!--- 802.1x or PSK authentication


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 8021X_REQD (3) Plumbed 
    mobile LWAPP rule on AP 00:1c:0j:ca:5f:c0

!--- PEM notifies the LWAPP component to add the new client on the AP with 
!--- a list of negotiated capabilities, rates, Qos, etc.



APF Process


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 apfPemAddUser2 (apf_policy.c:209) 
    Changing state for mobile 00:1b:77:42:07:69 on AP 00:1c:0j:ca:5f:c0 from 
    Probe to Associated

!--- APF notifies that client has been moved successfully into associated 
!--- state. 


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Stopping deletion of Mobile 
    Station: (callerId: 48)

!--- The expiration timer for client is removed, as now the session timeout 
!--- is taking place. This is also part of the above notification 
!--- (internal code callerId: 48).


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Sending Assoc Response to 
    station on BSSID 00:1c:0j:ca:5f:c0 (status 0)

!--- APF builds and sends the association response to client.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 apfProcessAssocReq 
    (apf_80211.c:3838) Changing state for mobile 00:1b:77:42:07:69 on AP 
    00:1c:0j:ca:5f:c0 from Associated to Associated

!--- The association response was sent successfully; now APF keeps the 
!--- client in associated state and sets the association timestamp on this point.



Dot1x Process


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Creating a new PMK Cache Entry 
    for station 00:1b:77:42:07:69 (RSN 0)

!--- APF calls Dot1x to allocate a new PMK cached entry for the client. 
!--- RSN is disabled (zero value).


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Initiating WPA PSK to mobile 
    00:1b:77:42:07:69

!--- Dot1x signals a new WPA or WPA2 PSK exchange with mobile.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 dot1x - moving mobile 
    00:1b:77:42:07:69 into 
    Force Auth state

!--- As no EAPOL authentication takes place, the client port is marked as 
!--- forced Auth. Dot1x performs key negotiation with PSK clients only.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Skipping EAP-Success to mobile 
    00:1b:77:42:07:69

!--- For PSK, CCKM or RSN, the EAP success is not sent to client, as there 
!--- was no EAPOL authentication taking place.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Sending EAPOL-Key Message to 
    mobile 
    00:1b:77:42:07:69

   state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00

!--- Dot1x starts the exchange to arrive into PTK. PMK is known, as this 
!--- is PSK auth. First message is ANonce.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Received EAPOL-Key from mobile 
    00:1b:77:42:07:69

!--- Message received from client.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Received EAPOL-key in PKT_START 
    state (message 2) from mobile 00:1b:77:42:07:69

!--- This signals the start of the validation of the second message 
!--- from client (SNonce+MIC). No errors are shown, so process continues. 
!--- Potential errors at this point could be: deflection attack (ACK bit 
!--- not set on key), MIC errors, invalid key type, invalid key length, etc.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Stopping retransmission timer 
    for mobile 00:1b:77:42:07:69

!--- Dot1x got an answer for message 1, so retransmission timeout is stopped.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Sending EAPOL-Key Message to 
    mobile 00:1b:77:42:07:69

   state PTKINITNEGOTIATING (message 3), replay counter 
    00.00.00.00.00.00.00.01

!--- Derive PTK; send GTK + MIC.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Received EAPOL-Key from mobile 
    00:1b:77:42:07:69

!--- Message received from client.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 Received EAPOL-key in 
    PTKINITNEGOTIATING state (message 4) from mobile 00:1b:77:42:07:69

!--- This signals the start of validation of message 4 (MIC), which 
!--- means client installed the keys. Potential errors after this message 
!--- are MIC validation errors, invalid key types, etc.



PEM Process


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 8021X_REQD (3) Change 
    state to L2AUTHCOMPLETE (4) last state L2AUTHCOMPLETE (4)

!--- PEM receives notification and signals the state machine to change to L2 
!--- authentication completed.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 L2AUTHCOMPLETE (4) 
    Plumbed mobile LWAPP rule on AP 00:1c:0j:ca:5f:c0

!--- PEM pushes client status and keys to AP through LWAPP component.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 L2AUTHCOMPLETE (4) 
    Change state to DHCP_REQD (7) last state DHCP_REQD (7)

>!--- PEM sets the client on address learning status.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 DHCP_REQD (7) 
    pemAdvanceState2 4238, Adding TMP rule

!--- PEM signals NPU to allow DHCP/ARP traffic to be inspected by controller 
!--- for the address learning.


Wed Oct 31 10:46:15 2007: 00:1b:77:42:07:69 0.0.0.0 DHCP_REQD (7) 
    Adding Fast Path rule

  type = Airespace AP - Learn IP address

  on AP 00:1c:0j:ca:5f:c0, slot 1, interface = 1, QOS = 0

  ACL Id = 255, Jumbo Frames = NO, 802.1P = 0, DSCP = 0, TokenID = 5006

!--- Entry is built for client and prepared to be forwarded to NPU. 
!--- Type is 9 (see the table in the Client Traffic Forwarding section of 
!--- this document) to allow controller to learn the IP address.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 0.0.0.0 DHCP_REQD (7) 
    Successfully plumbed mobile rule (ACL ID 255)

!--- A new rule is successfully sent to internal queue to add the client 
!--- to the NPU.



Dot1x Process


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 Stopping retransmission timer 
    for mobile 00:1b:77:42:07:69

!--- Dot1x received message from client.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 Sending EAPOL-Key Message to 
    mobile 00:1b:77:42:07:69

   state PTKINITDONE (message 5 - group), replay counter 
    00.00.00.00.00.00.00.02

!--- Group key update prepared for client.



PEM Process


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 0.0.0.0 Added NPU entry of type 9

!--- NPU reports that entry of type 9 is added (learning address state). 
!--- See the table in the Client Traffic Forwarding section of this document.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 Sent an XID frame

!--- No address known yet, so the controller sends only XID frame 
!--- (destination broadcast, source client address, control 0xAF).



Dot1x Process


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 Sent EAPOL-Key M5 for mobile 
    00:1b:77:42:07:69

!--- Key update sent.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 Received EAPOL-Key from mobile 
    00:1b:77:42:07:69

!--- Key received.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 Received EAPOL-key in 
    REKEYNEGOTIATING state (message 6) from mobile 00:1b:77:42:07:69

!--- Successfully received group key update.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 Stopping retransmission timer 
    for mobile 00:1b:77:42:07:69

!--- Group key timeout is removed.



DHCP Process


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 DHCP received op BOOTREQUEST 
    (1) (len 308, port 1, encap 0xec03)

!--- First DHCP message received from client.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 DHCP dropping packet due to 
    ongoing mobility handshake exchange, (siaddr 0.0.0.0,  mobility 
    state = 'apfMsMmQueryRequested'


PEM Process


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 0.0.0.0 DHCP_REQD (7) mobility 
    role update request from Unassociated to Local

  Peer = 0.0.0.0, Old Anchor = 0.0.0.0, New Anchor = 192.168.100.11

!--- NPU is notified that this controller is the local anchor, so to 
!--- terminate any previous mobility tunnel. As this is a new client, 
!--- old address is empty.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 0.0.0.0 DHCP_REQD (7) State 
    Update from Mobility-Incomplete to Mobility-Complete, mobility 
    role=Local

!--- Role change was successful.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 0.0.0.0 DHCP_REQD (7) 
    pemAdvanceState2 3934, Adding TMP rule

!--- Adding temporary rule to NPU for address learning now with new mobility 
!--- role as local controller.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 0.0.0.0 DHCP_REQD (7) 
    Replacing Fast Path rule

  type = Airespace AP - Learn IP address

  on AP 00:1c:0j:ca:5f:c0, slot 1, interface = 1, QOS = 0

  ACL Id = 255, Jumbo Frames = NO, 802.1P = 0, DSCP = 0, TokenID = 5006

!--- Entry is built.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 0.0.0.0 DHCP_REQD (7)  
    Successfully plumbed mobile rule (ACL ID 255)

!--- A new rule is successfully sent to internal queue to add the 
!--- client to the NPU.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 0.0.0.0 Added NPU entry of type 9

!--- Client is on address learning state; see the table in the 
!--- Client Traffic Forwarding section of this document. Now mobility 
!--- has finished.


Wed Oct 31 10:46:19 2007: 00:1b:77:42:07:69 Sent an XID frame

!--- No address known yet, so controller sends only XID frame (destination 
!--- broadcast, source client address, control 0xAF).



DHCP Process


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP received op BOOTREQUEST 
    (1) (len 308, port 1, encap 0xec03)

!--- DHCP request from client.


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP selecting relay 1 -  
    control block settings:

                    dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0,

                    dhcpGateway: 0.0.0.0, dhcpRelay: 0.0.0.0  VLAN: 0

!--- Based on the WLAN configuration, the controller selects the identity to 
!--- use to relay the DHCP messages.


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP selected relay 1 -  
    192.168.100.254 (local address 192.168.100.11, gateway 192.168.100.254, 
    VLAN 100, port 1)

!--- Interface selected.


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP  
    transmitting DHCP DISCOVER (1)

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    xid: 0xd3d3b6e9 (3553867497), secs: 1024, flags: 0

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    chaddr: 00:1b:77:42:07:69

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    ciaddr: 0.0.0.0,  yiaddr: 0.0.0.0

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    siaddr: 0.0.0.0,  giaddr: 192.168.100.11

!--- Debug parsing of the frame sent. The most important fields are included.


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP sending REQUEST to  
    192.168.100.254 (len 350, port 1, vlan 100)


!--- DHCP request forwarded.


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP selecting relay 2 -  
    control block settings:

                    dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0,

                    dhcpGateway: 0.0.0.0, dhcpRelay: 192.168.100.11  VLAN: 100

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP selected relay 2 ? NONE

!--- No secondary server configured, so no additional DHCP request are 
!--- prepared (configuration dependant).


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP received op BOOTREPLY (2)  
    (len 308, port 1, encap 0xec00)

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP setting server from OFFER  
    (server 192.168.100.254, yiaddr 192.168.100.105)

!--- DHCP received for a known server. Controller discards any offer not on 
!--- the DHCP server list for the WLAN/Interface.


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP sending REPLY to STA  
    (len 416, port 1, vlan 100)

!--- After building the DHCP reply for client, it is sent to AP for forwarding.


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP transmitting DHCP OFFER (2)

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    xid: 0xd3d3b6e9 (3553867497), secs: 0, flags: 0

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    chaddr: 00:1b:77:42:07:69

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    ciaddr: 0.0.0.0,  yiaddr: 192.168.100.105

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    siaddr: 0.0.0.0,  giaddr: 0.0.0.0

Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP    
    server id: x.x.x.x  rcvd server id: 192.168.100.254


!--- Debug parsing of the frame sent. The most important fields are included.


Wed Oct 31 10:46:21 2007: 00:1b:77:42:07:69 DHCP received op BOOTREQUEST (1) 
    (len 316, port 1, encap 0xec03)

!--- Client answers


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP selecting relay 1 -  
    control block settings:

                    dhcpServer: 192.168.100.254, dhcpNetmask: 0.0.0.0,

                    dhcpGateway: 0.0.0.0, dhcpRelay: 192.168.100.11  VLAN: 100

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP selected relay 1 -
    192.168.100.254 (local address 192.168.100.11, gateway 192.168.100.254, 
    VLAN 100, port 1)

!--- DHCP relay selected per WLAN config


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP transmitting DHCP REQUEST (3)

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    xid: 0xd3d3b6e9 (3553867497), secs: 1024, flags: 0

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    chaddr: 00:1b:77:42:07:69

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    ciaddr: 0.0.0.0,  yiaddr: 0.0.0.0

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    siaddr: 0.0.0.0,  giaddr: 192.168.100.11

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    requested ip: 192.168.100.105

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    server id: 192.168.100.254  rcvd server id: x.x.x.x

!--- Debug parsing of the frame sent. The most important fields are included.


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP sending REQUEST to  
    192.168.100.254 (len 358, port 1, vlan 100)

!--- Request sent to server.


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP selecting relay 2 -  
    control block settings:

                    dhcpServer: 192.168.100.254, dhcpNetmask: 0.0.0.0,

                    dhcpGateway: 0.0.0.0, dhcpRelay: 192.168.100.11  VLAN: 100

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP selected relay 2 ? NONE

!--- No other DHCP server configured.


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP received op BOOTREPLY  
    (2) (len 308, port 1, encap 0xec00)

!--- Server sends a DHCP reply, most probably an ACK (see below).



PEM Process


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 192.168.100.105 DHCP_REQD  
    (7) Change state to RUN (20) last state RUN (20)

!--- DHCP negotiation successful, address is now known, and client 
!--- is moved to RUN status.


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 192.168.100.105 RUN (20)  
    Reached PLUMBFASTPATH: from line 4699

!--- No L3 security; client entry is sent to NPU.


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 192.168.100.105 RUN (20)  
    Replacing Fast Path rule

  type = Airespace AP Client

  on AP 00:1c:0j:ca:5f:c0, slot 1, interface = 1, QOS = 0

  ACL Id = 255, Jumbo Frames = NO, 802.1P = 0, DSCP = 0, TokenID = 5006

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 192.168.100.105 RUN (20)  
    Successfully plumbed mobile rule (ACL ID 255)


DHCP Process


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 Assigning Address  
    192.168.100.105 to mobile 

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP sending REPLY to STA  
    (len 416, port 1, vlan 100)

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP transmitting DHCP ACK (5)

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    xid: 0xd3d3b6e9 (3553867497), secs: 0, flags: 0

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    chaddr: 00:1b:77:42:07:69

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    ciaddr: 0.0.0.0,  yiaddr: 192.168.100.105

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    siaddr: 0.0.0.0,  giaddr: 0.0.0.0

Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 DHCP    
    server id: x.x.x.x  rcvd server id: 192.168.100.254


PEM Process


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 192.168.100.105 Added NPU  
    entry of type 1


!--- Client is now successfully associated to controller. 
!--- Type is 1; see the table in the Client Traffic Forwarding 
!--- section of this document.


Wed Oct 31 10:46:25 2007: 00:1b:77:42:07:69 Sending a gratuitous ARP for  
    192.168.100.105, VLAN Id 100

!--- As address is known, gratuitous ARP is sent to notify.

Ejemplos de Troubleshooting

Configuración de cifrado de cliente incorrecta

Este ejemplo muestra un cliente con capacidades diferentes al AP. El cliente sondea el SSID, pero como la solicitud de sondeo muestra algunos parámetros no admitidos, el cliente nunca pasa a las fases de autenticación/asociación.

En particular, el problema introducido fue una discordancia entre el cliente que utiliza WPA, y el AP que anuncia solamente soporte WPA2:

Wed Oct 31 10:51:37 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 23) in 5 seconds
Wed Oct 31 10:51:37 2007: 00:1b:77:42:07:69 apfProcessProbeReq 
    (apf_80211.c:4057) Changing state for mobile 00:1b:77:42:07:69 on AP 
    00:1c:b0:ea:5f:c0 from Idle to Probe

!--- Controller adds the new client, moving into probing status

Wed Oct 31 10:51:37 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:38 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:38 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds

!--- AP is reporting probe activity every 500 ms as configured

Wed Oct 31 10:51:41 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:41 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:41 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:41 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:44 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:44 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:44 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:44 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:51:49 2007: 00:1b:77:42:07:69 apfMsExpireCallback (apf_ms.c:433) 
    Expiring Mobile!
Wed Oct 31 10:51:49 2007: 00:1b:77:42:07:69 0.0.0.0 START (0) Deleted mobile 
    LWAPP rule on AP [00:1c:b0:ea:5f:c0]
Wed Oct 31 10:51:49 2007: 00:1b:77:42:07:69 Deleting mobile on AP 
    00:1c:b0:ea:5f:c0(0)

!--- After 5 seconds of inactivity, client is deleted, never moved into 
!--- authentication or association phases.

Clave previamente compartida incorrecta

Esto muestra que el cliente intenta autenticarse mediante WPA-PSK en la infraestructura, pero falla debido a la discordancia de la clave previamente compartida entre el cliente y el controlador, lo que resulta en la eventual adición del cliente a la lista de exclusión (bloqueo):

Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Adding mobile on LWAPP AP 
    00:1c:b0:ea:5f:c0(0) 
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 23) in 5 seconds
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 apfProcessProbeReq (apf_80211.c:
    4057) Changing state for mobile 00:1b:77:42:07:69 on AP 00:1c:b0:ea:5f:c0 
    from Idle to Probe
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 24) in 5 seconds
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Association received from mobile 
    on AP 00:1c:b0:ea:5f:c0
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 STA - rates (8): 130 132 139 150 
    12 18 24 36 0 0 0 0 0 0 0 0
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 STA - rates (12): 130 132 139 150 
    12 18 24 36 48 72 96 108 0 0 0 0
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Processing WPA IE type 221, 
    length 24 for mobile 00:1b:77:42:07:69
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 0.0.0.0 START (0) 
    Initializing policy
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 0.0.0.0 START (0) Change state to 
    AUTHCHECK (2) last state AUTHCHECK (2)
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 0.0.0.0 AUTHCHECK (2) Change 
    state to 8021X_REQD (3) last state 8021X_REQD (3)
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 0.0.0.0 8021X_REQD (3) Plumbed 
    mobile LWAPP rule on AP 00:1c:b0:ea:5f:c0
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 apfPemAddUser2 (apf_policy.c:209) 
    Changing state for mobile 00:1b:77:42:07:69 on AP 00:1c:b0:ea:5f:c0 from 
    Probe to Associated
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Stopping deletion of Mobile 
    Station: (callerId: 48)
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Sending Assoc Response to station 
    on BSSID 00:1c:b0:ea:5f:c0 (status 0)
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 apfProcessAssocReq (apf_80211.c:
    3838) Changing state for mobile 00:1b:77:42:07:69 on AP 00:1c:b0:ea:5f:c0 
    from Associated to Associated
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Creating a new PMK Cache Entry 
    for station 00:1b:77:42:07:69 (RSN 0)
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Initiating WPA PSK to mobile 
    00:1b:77:42:07:69
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 dot1x - moving mobile 
    00:1b:77:42:07:69 into Force Auth state
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Skipping EAP-Success to mobile 
    00:1b:77:42:07:69
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Sending EAPOL-Key Message to 
    mobile 00:1b:77:42:07:69
state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Received EAPOL-Key from mobile 
    00:1b:77:42:07:69
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Received EAPOL-key in PKT_START 
    state (message 2) from mobile 00:1b:77:42:07:69
Wed Oct 31 10:55:55 2007: 00:1b:77:42:07:69 Received EAPOL-key M2 with 
    invalid MIC from mobile 00:1b:77:42:07:69
Wed Oct 31 10:55:56 2007: 00:1b:77:42:07:69 802.1x 'timeoutEvt' Timer expired 
    for station 00:1b:77:42:07:69
Wed Oct 31 10:55:56 2007: 00:1b:77:42:07:69 Retransmit 1 of EAPOL-Key M1 
    (length 99) for mobile 00:1b:77:42:07:69
Wed Oct 31 10:55:56 2007: 00:1b:77:42:07:69 Received EAPOL-Key from mobile 
    00:1b:77:42:07:69
Wed Oct 31 10:55:56 2007: 00:1b:77:42:07:69 Received EAPOL-key in PKT_START 
    state (message 2) from mobile 00:1b:77:42:07:69
Wed Oct 31 10:55:56 2007: 00:1b:77:42:07:69 Received EAPOL-key M2 with invalid 
    MIC from mobile 00:1b:77:42:07:69

!--- MIC error due to wrong preshared key

Wed Oct 31 10:55:57 2007: 00:1b:77:42:07:69 802.1x 'timeoutEvt' Timer expired 
    for station 00:1b:77:42:07:69
Wed Oct 31 10:55:57 2007: 00:1b:77:42:07:69 Retransmit 2 of EAPOL-Key M1 
    (length 99) for mobile 00:1b:77:42:07:69
Wed Oct 31 10:55:57 2007: 00:1b:77:42:07:69 Received EAPOL-Key from mobile 
    00:1b:77:42:07:69
Wed Oct 31 10:55:57 2007: 00:1b:77:42:07:69 Received EAPOL-key in PKT_START 
    state (message 2) from mobile 00:1b:77:42:07:69
Wed Oct 31 10:55:57 2007: 00:1b:77:42:07:69 Received EAPOL-key M2 with invalid 
    MIC from mobile 00:1b:77:42:07:69
Wed Oct 31 10:55:58 2007: 00:1b:77:42:07:69 802.1x 'timeoutEvt' Timer expired 
    for station 00:1b:77:42:07:69
Wed Oct 31 10:55:58 2007: 00:1b:77:42:07:69 Retransmit failure for EAPOL-Key 
    M1 to mobile 00:1b:77:42:07:69, retransmit count 3, mscb deauth count 0
Wed Oct 31 10:55:58 2007: 00:1b:77:42:07:69 Sent Deauthenticate to mobile on 
    BSSID 00:1c:b0:ea:5f:c0 slot 0(caller 1x_ptsm.c:462)

!--- Client is deauthenticated, after three retries



!--- The process is repeated three times, until client is block listed

 
Wed Oct 31 10:56:10 2007: 00:1b:77:42:07:69 Block listing (if enabled) mobile 
    00:1b:77:42:07:69
Wed Oct 31 10:56:10 2007: 00:1b:77:42:07:69 apfBlacklistMobileStationEntry2 
    (apf_ms.c:3560) Changing state for mobile 00:1b:77:42:07:69 on AP 
    00:1c:b0:ea:5f:c0 from Associated to Exclusion-list (1)
Wed Oct 31 10:56:10 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 44) in 10 seconds
Wed Oct 31 10:56:10 2007: 00:1b:77:42:07:69 0.0.0.0 8021X_REQD (3) Change 
    state to START (0) last state 8021X_REQD (3)
Wed Oct 31 10:56:10 2007: 00:1b:77:42:07:69 0.0.0.0 START (0) Reached FAILURE: 
    from line 3522
Wed Oct 31 10:56:10 2007: 00:1b:77:42:07:69 Scheduling deletion of Mobile 
    Station:  (callerId: 9) in 10 seconds

Información Relacionada

• Soporte técnico y descargas de Cisco