某大学无线MESH链路建立异常问题处理经验案例

客户反馈MESH建立异常，MAP的以太口插上一根网线使得以太口up后，MAP就能在AC上注册成功MESH-LINK建立问题，否则MESH-LINK建立时断时连。

第一步：MESH作为一个基础协议，一般而言不该出现问题，所以先检查配置，发现MAP（mesh access）配置一处错误，“portal-service enable”含义是当前MP使能入口功能，或者可以理解输入这段指令，AP角色就变成了MPP（mesh portal point）。

wlan ap map model WA2620i-AGN id 779

 priority level 7

 serial-id 219801A0CNC127000117

 portal-service enable

 radio 1

  channel 149

  mp-policy 1

  mesh-profile 1

  mesh peer-mac-address 70f9-6d11-4512

  radio enable

 radio 2

  service-template 1 vlan-id 751

  service-template 2 vlan-id 77

  service-template 3

  radio enable

第二步：按照客户的配置在实验室中尝试复现，正常配置MESH-LINK建立正常；MAP上配置了portal-service enable，MESH-LINK无法连接。按照客户的办法，在MAP上接一根网线，使接口up，这样MESH就能建立，而实验室的MAP接上有线后，meshlink起来一段时间又会断开，和客户现场现象不同。指导客户删除该命令后现象依旧是：MAP的以太口插上一根网线使得以太口up后，MAP就能在AC上注册成功MESH-LINK建立问题，否则MESH-LINK建立时断时连。

第三步：在客户现场的MAP上debug wlan mesh all，显示异常

*May  8 15:31:13:981 2015 map WMSH/7/Event:  Channel 5 is detected in zero cfg state

*May  8 15:31:14:175 2015 map WMSH/7/Event:  Channel 13 is detected in zero cfg state

*May  8 15:31:14:391 2015 map WMSH/7/Event:  Channel 4 is detected in zero cfg state

*May  8 15:31:14:593 2015 map WMSH/7/Event:  Channel 12 is detected in zero cfg state

*May  8 15:31:14:744 2015 map WMSH/7/Event:  Channel 3 is detected in zero cfg state

*May  8 15:31:14:910 2015 map WMSH/7/Event:  Channel 11 is detected in zero cfg state

*May  8 15:31:15:139 2015 map WMSH/7/Event:  Channel 2 is detected in zero cfg state

*May  8 15:31:15:305 2015 map WMSH/7/Event:  Channel 10 is detected in zero cfg state

*May  8 15:31:15:487 2015 map WMSH/7/Event:  Channel 1 is detected in zero cfg state

*May  8 15:31:15:927 2015 map WMSH/7/Event:  Channel 8 is detected in zero cfg state

*May  8 15:31:17:559 2015 map WMSH/7/Event:  Channel scan ended for the radio: 1 in Mode: 2

*May  8 15:31:18:377 2015 map WMSH/7/Event:  Channel 9 is detected in zero cfg state

*May  8 15:31:18:950 2015 map WMSH/7/Event:  Channel scan ended for the radio: 2 in Mode: 1

*May  8 15:31:27:788 2015 map WMSH/7/Event:   Reset sequence number generate method to diver

*May  8 15:31:27:788 2015 map WMSH/7/Event:  Active scanning is started for radio 1 in mode 2

*May  8 15:31:27:789 2015 map WMSH/7/Event:   Reset sequence number generate method to diver

*May  8 15:31:27:789 2015 map WMSH/7/Event:  Active scanning is started for radio 2 in mode 4

*May  8 15:31:27:789 2015 map WMSH/7/Event:  The neighbor 80f6-2e12-5300 is detected during zero configuration scan

*May  8 15:31:28:709 2015 map WMSH/7/Event:  Channel scan ended for the radio: 1 in Mode: 2

*May  8 15:31:33:126 2015 map WMSH/7/Event:  Channel scan ended for the radio: 2 in Mode: 4

*May  8 15:31:33:126 2015 map WMSH/7/Event:   Reset sequence number generate method to diver

*May  8 15:31:33:126 2015 map WMSH/7/Event:  Active scanning is started for radio 2 in mode 1

*May  8 15:31:38:490 2015 map WMSH/7/Event:  Channel scan ended for the radio: 2 in Mode: 1

*May  8 15:31:47:851 2015 map WMSH/7/Event:  Zero configuration state active scanning is finished

*May  8 15:31:47:851 2015 map WMSH/7/Event:  MA 70f9-6d64-57e0 Kdk fsm move to idle.

*May  8 15:31:47:851 2015 map WMSH/7/Event:  ZeroCfg neighbor selection is triggered for 80f6-2e12-5300

*May  8 15:31:47:851 2015 map WMSH/7/Timer:  Create check-link timer

*May  8 15:31:47:851 2015 map WMSH/7/Event:  The selector for the link is 80f6-2e12-5300

*May  8 15:31:47:851 2015 map WMSH/7/Timer:  Neighbor age timer is stopped for neighbor 80f6-2e12-5300

*May  8 15:31:47:851 2015 map WMSH/7/Timer:  Random link initialization timer is started for neighbor 80f6-2e12-5300

*May  8 15:31:47:851 2015 map WMSH/7/Event:  Peer Link Establishment process started for neighbor 80f6-2e12-5300

*May  8 15:31:47:852 2015 map WMSH/7/Fsm:  LINK FSM Change state [Idle -> Listen] for neighbor 80f6-2e12-5300

*May  8 15:31:48:230 2015 map WMSH/7/Timer:  Random link initialization timer expired for neighbor 80f6-2e12-5300

*May  8 15:31:48:230 2015 map WMSH/7/Frame_Send:  Peer link open frame is being sent to neighbor 80f6-2e12-5300 in state Listen

*May  8 15:31:48:230 2015 map WMSH/7/Timer:  Retry timer is started for neighbor 80f6-2e12-5300

*May  8 15:31:48:230 2015 map WMSH/7/Fsm:  LINK FSM Change state [Listen -> OpenSent] for neighbor 80f6-2e12-5300

*May  8 15:31:48:232 2015 map WMSH/7/Frame_Rcvd:  Peer link open frame is received from neighbor 80f6-2e12-5300

*May  8 15:31:48:232 2015 map WMSH/7/Frame_Send:  Peer link confirm frame is being sent to neighbor 80f6-2e12-5300 in state OpenSent

*May  8 15:31:48:232 2015 map WMSH/7/Fsm:  LINK FSM Change state [OpenSent -> OpenRcvd] for neighbor 80f6-2e12-5300

*May  8 15:31:48:238 2015 map WMSH/7/Frame_Rcvd:  Peer link confirm frame is received from neighbor 80f6-2e12-5300

*May  8 15:31:48:238 2015 map WMSH/7/Timer:  Retry timer is stopped for neighbor 80f6-2e12-5300

*May  8 15:31:48:238 2015 map WMSH/7/Fsm:  LINK FSM Change state [OpenRcvd -> Established] for neighbor 80f6-2e12-5300

*May  8 15:31:48:299 2015 map WMSH/7/Event:  Link information added successfully to driver for neighbor 80f6-2e12-5300

*May  8 15:31:48:439 2015 map WMSH/7/Event:  Mesh security authentication bypassed since the device [70f9-6d64-57e0] or peer [80f6-2e12-5300] is in zero configuration state

*May  8 15:31:48:619 2015 map WMSH/7/Event:  Temporary link is established with [80f6-2e12-5300]

*May  8 15:31:57:830 2015 map WMSH/7/Timer:  Check link time age out

第四步：根据第三步所查看信息可知，AP已经信道扫描建立临时邻居后断开临时链路再次建立安全MESH-LINK时检测链路超时了。打开log信息查看发现接口反复up、down引起的MESH链路反复建立断开：

%Apr 28 18:02:39:056 2015 map IFNET/3/LINK_UPDOWN: Vlan-interface1 link status is UP.

%Apr 28 18:02:39:056 2015 map IFNET/5/LINEPROTO_UPDOWN: Line protocol on the interface Vlan-interface1 is UP.

%Apr 28 18:02:43:728 2015 map LWPC/6/LWPC_AP_UP: 

 Connection with AC 192.168.16.2 goes operational.

%Apr 28 18:02:44:894 2015 map IFNET/3/LINK_UPDOWN: WLAN-MESHLINK5 link status is DOWN.

%Apr 28 18:02:44:894 2015 map WMSH/6/WMESH_PEER_LINK_CLOSED:  Peer link is closed with neighbor 80f6-2e12-5300 for reason:LINK_CANCELLED.

%Apr 28 18:02:44:894 2015 map WMSH/6/WMESH_EXIT_ZERO_CFG_STATE:  The device has exited zero configuration state.

%Apr 28 18:02:44:896 2015 map IFNET/3/LINK_UPDOWN: Vlan-interface1 link status is DOWN.

%Apr 28 18:02:45:101 2015 map IFNET/5/LINEPROTO_UPDOWN: Line protocol on the interface Vlan-interface1 is DOWN.

%Apr 28 18:02:48:542 2015 map WMSH/6/WMESH_AUTHENTICATOR:  The device 70f9-6d64-57e0 is an authenticator.

%Apr 28 18:02:48:765 2015 map IFNET/3/LINK_UPDOWN: WLAN-MESHLINK6 link status is UP.

%Apr 28 18:02:48:765 2015 map WMSH/6/WMESH_PEER_LINK_ESTABLISH:  Peer link is established with neighbor 80f6-2e12-5300 in MESH WLAN-LINK,on radio 1 with BSSID 70f9-6d64-57e0.

%Apr 28 18:02:48:771 2015 map IFNET/3/LINK_UPDOWN: Vlan-interface1 link status is UP.

%Apr 28 18:02:48:771 2015 map IFNET/5/LINEPROTO_UPDOWN: Line protocol on the interface Vlan-interface1 is UP.

%Apr 28 18:02:48:777 2015 map WMSH/6/WMESH_AUTH_SUCCESS:  Authentication success with neighbor 80f6-2e12-5300 in MESH WLAN-LINK,on radio 1 with BSSID 70f9-6d64-57e0.

%Apr 28 18:03:15:143 2015 map IFNET/3/LINK_UPDOWN: WLAN-MESHLINK6 link status is DOWN.

%Apr 28 18:03:15:143 2015 map WMSH/6/WMESH_PEER_LINK_CLOSED:  Peer link is closed with neighbor 80f6-2e12-5300 for reason:CLOSE_RCVD.

%Apr 28 18:03:15:146 2015 map IFNET/3/LINK_UPDOWN: Vlan-interface1 link status is DOWN.

%Apr 28 18:03:15:146 2015 map IFNET/5/LINEPROTO_UPDOWN: Line protocol on the interface Vlan-interface1 is DOWN.

%Apr 28 18:03:15:308 2015 map IFNET/3/LINK_UPDOWN: WLAN-MESHLINK7 link status is UP.

第五步： MESH-LINK链路和物理层以太口up、down都没有关系与VLAN接口有关，回忆MESH原理：设备上电启动后扫描信道建立临时MESH链路，触发DHCP获取IP地址，触发LWAPP发现过程，建立LWAPP隧道，通过LWAPP从AC获取配置，建立安全MESH链路，完成MESH节点配置。也就是说VLAN接口down了导致MESH链路断开，那么VLAN接口为什么会down呢？首先display int vlan 1查看发现vlan接口地址时有时无，查看接口地址状态发现状态不稳定：

Vlan-interface1 DHCP client information:

 Current machine state: HALT

dis dhcp  client  interface  vlan 1

Vlan-interface1 DHCP client information:

 Current machine state: REQUESTING

 Offered IP: 192.168.12.80 255.255.252.0, lease: 600 seconds

 DHCP server: 192.168.12.1

                            Display AP Profile

-------------------------------------------------------------------------------

 Model Number                  : WA2620-AGN-S

 Serial-ID                     : 219801A0H69145Q01522

 AP Address                    : Trying for IPv4 address

 H/W Version                   : Ver.A

 S/W Version                   : V100R005B09D027(279072128)

 Boot Version                  : 3.02

 Device State                  : Zero configuration state

 

 Master AC:

 Description                   : -NA-

 AC Address                    : -NA-

 State                         : BDisc

 Transmitted control packets   : 0

 Received control packets      : 0

 Transmitted data packets      : 0

 Received data packets         : 0

 

 Latest AC IP address          : 192.168.16.2

 Tunnel Down Reason            : Response Timer Expire

 

-------------------------------------------------------------------------------

 Unicast static AC IPv4 address: Not Configured

 Unicast static AC IPv6 address: Not Configured

-------------------------------------------------------------------------------

既然接口地址有问题引起MESH异常，那么我们就MAP配置vlan地址，AC地址以及一条指向网关的静态路由，很快mesh链路建立起来并且不会断开，初步判断是dhcp问题：

                              Peer Link Information

-------------------------------------------------------------------------------

 Nbr-Mac(rssi)     BSSID         Interface        Link-state  Uptime(hh:mm:ss)

-------------------------------------------------------------------------------

 80f6-2e12-5300(37) 70f9-6d64-57e0 WLAN-MESHLINK7    Active(T)     0: 5: 16

-------------------------------------------------------------------------------

第六步：在MAP上收集DHCP信息：

*May 21 11:19:17:006 2015 map DHCPC/7/DHCPC_EVENT:

  Vlan-interface1: Resend DHCPREQUEST for enough times. Move to INIT state.

*May 21 11:19:17:006 2015 map DHCPC/7/DHCPC_EVENT:

  Vlan-interface1: FSM state transfers (REQUESTING-->INIT) successfully.

*May 21 11:19:17:006 2015 map DHCPC/7/DHCPC_EVENT:

  Vlan-interface1: DHCPDISCOVER will be sent in 10 ms.

*May 21 11:19:17:016 2015 map DHCPC/7/DHCPC_PACKET:

  Vlan-interface1: Send a DHCP packet...

  Head: op (BOOTPREQUEST); htype (ETHERNET); hlen (6); xid (0x462a3522);

  ciaddr (0.0.0.0); yiaddr (0.0.0.0); chaddr (70f9-6d64-57e0);

  Options:

    63 82 53 63 35 01 01 0C 1E 57 41 32 36 32 30 2D

    41 47 4E 2D 53 2D 37 30 2D 66 39 2D 36 64 2D 36

    34 2D 35 37 2D 65 30 32 04 C0 A8 0C 50 37 08 01

    79 03 06 0F 21 2B 8A 39 02 04 80 3C 15 48 33 43

    2E 20 48 33 43 20 57 41 32 36 32 30 2D 41 47 4E

    2D 53 3D 07 01 70 F9 6D 64 57 E0 FF

 

*May 21 11:19:17:016 2015 map DHCPC/7/DHCPC_EVENT:

  Vlan-interface1: Sending DHCPDISCOVER packet succeeded.

*May 21 11:19:17:016 2015 map DHCPC/7/DHCPC_EVENT:

  Vlan-interface1: FSM state transfers (INIT-->SELECTING) successfully.

*May 21 11:19:17:530 2015 map DHCPC/7/DHCPC_EVENT:

  Vlan-interface1: Receive a packet.

*May 21 11:19:17:530 2015 map DHCPC/7/DHCPC_PACKET:

  Vlan-interface1: Decode option 43:

    80 07 00 00 01 C0 A8 10 02

 

*May 21 11:19:17:530 2015 map DHCPC/7/DHCPC_PACKET:

  Vlan-interface1: Receive a DHCP packet...

  Head: op (BOOTPREPLY); htype (ETHERNET); hlen (6); xid (0x462a3522);

  ciaddr (0.0.0.0); yiaddr (192.168.12.80); chaddr (70f9-6d64-57e0);

  Option: type (DHCPOFFER); mask (255.255.252.0); lease (600);

  T1 (300); T2 (525); server (192.168.12.1); default router (192.168.12.1); Boot server (192.168.16.2)

*May 21 11:19:17:530 2015 map DHCPC/7/DHCPC_EVENT:

  Vlan-interface1: Select 192.168.12.1 as the server.

*May 21 11:19:17:530 2015 map DHCPC/7/DHCPC_PACKET:

  Vlan-interface1: Send a DHCP packet...

  Head: op (BOOTPREQUEST); htype (ETHERNET); hlen (6); xid (0x462a3522);

  ciaddr (0.0.0.0); yiaddr (0.0.0.0); chaddr (70f9-6d64-57e0);

  Options:

    63 82 53 63 35 01 03 0C 1E 57 41 32 36 32 30 2D

    41 47 4E 2D 53 2D 37 30 2D 66 39 2D 36 64 2D 36

    34 2D 35 37 2D 65 30 32 04 C0 A8 0C 50 36 04 C0

    A8 0C 01 37 08 01 79 03 06 0F 21 2B 8A 39 02 04

    80 3C 15 48 33 43 2E 20 48 33 43 20 57 41 32 36

    32 30 2D 41 47 4E 2D 53 3D 07 01 70 F9 6D 64 57

    E0 FF

 

*May 21 11:19:17:531 2015 map DHCPC/7/DHCPC_EVENT:

  Vlan-interface1: Sending DHCPREQUEST packet succeeded

*May 21 11:19:17:591 2015 map DHCPC/7/DHCPC_EVENT:

  Vlan-interface1: FSM state transfers (SELECTING-->REQUESTING) successfully.

*May 21 11:19:17:731 2015 map DHCPC/7/DHCPC_EVENT:

  Vlan-interface1: Receive a packet

*May 21 11:19:17:831 2015 map DHCPC/7/DHCPC_PACKET:

  Vlan-interface1: Decode option 43:

    80 07 00 00 01 C0 A8 10 02

 

*May 21 11:19:17:971 2015 map DHCPC/7/DHCPC_PACKET:

  Vlan-interface1: Receive a DHCP packet...

  Head: op (BOOTPREPLY); htype (ETHERNET); hlen (6); xid (0x462a3522);

  ciaddr (0.0.0.0); yiaddr (192.168.12.80); chaddr (70f9-6d64-57e0);

  Option: type (DHCPACK); mask (255.255.252.0); lease (600);

  T1 (300); T2 (525); server (192.168.12.1); default router (192.168.12.1); Boot server (192.168.16.2)

*May 21 11:19:18:432 2015 map DHCPC/7/DHCPC_EVENT:

  Vlan-interface1: Begin to detect IP address conflict via ARP.

*May 21 11:19:18:552 2015 map DHCPC/7/DHCPC_EVENT:

  Vlan-interface1: Sending ARP request for address (192.168.12.80) succeeded.

*May 21 11:19:18:692 2015 map DHCPC/7/DHCPC_EVENT:

  Vlan-interface1: Move to BOUND state if no ARP reply is received in 1500 milliseconds.

*May 21 11:19:19:036 2015 map DHCPC/7/DHCPC_EVENT:

  Vlan-interface1: Receive no ARP reply for 192.168.12.80, so begin to use the address.

*May 21 11:19:19:036 2015 map DHCPC/7/DHCPC_EVENT:

  Vlan-interface1: FSM state transfers (REQUESTING-->BOUND) successfully.

*May 21 11:19:19:117 2015 map DHCPC/7/DHCPC_EVENT:

  Vlan-interface1: Notify route module to add the default gateway: destination (0.0.0.0), mask (0.0.0.0), nexthop (192.168.12.1).

*May 21 11:19:19:317 2015 map DHCPC/7/DHCPC_EVENT:

  Vlan-interface1: Sending ARP request for address (192.168.12.1) succeeded.

%May 21 11:19:35:086 2015 map IFNET/3/LINK_UPDOWN: WLAN-MESHLINK19 link status is DOWN.

%May 21 11:19:35:086 2015 map WMSH/6/WMESH_PEER_LINK_CLOSED:  Peer link is closed with neighbor 80f6-2e12-5300 for reason:LINK_CANCELLED.

%May 21 11:19:35:087 2015 map WMSH/6/WMESH_EXIT_ZERO_CFG_STATE:  The device has exited zero configuration state.

%May 21 11:19:35:089 2015 map IFNET/3/LINK_UPDOWN: Vlan-interface1 link status is DOWN.

从DHCP的debug看，报文有请求有回复似乎也不是DHCP的问题！为了保险起见在DHCP中继和MPP的中间有线做了镜像抓包。

发现dhcp请求和回应均是成对出现，与此前某局点MESH相同现象dhcp server的安全机制不允许相同client在短时间内连续申请IP地址引起的问题不一样。继续观察发现一个很奇怪的现象，DHCP中继回复的报文有的是广播有的是单播，打开1270号报文dhcp discover继续观察，发现报文标志位要求广播回复：

打开1326号报文dhcp offer观察，中继设备回复的报文为广播：

 

打开1327号报文DHCP request观察，标志位要求广播：

打开1328号报文DHCP ACK，DHCP relay回复报文为广播：

而之后的DHCP ACK却变成了单播包：

这是因为MESH-LINK建立需要两次DHCP申请拿地址过程，第一次dhcp中继设备回复报文是MAP要求的广播ACK，而第二次回复的ACK确实单播的，导致VLAN接口异常，LWAPP无法建立，从而不能建立稳定的MESH连接。为了进一步核实想法，在实验室搭建了测试环境，使用我司交换机作为DHCP中继，抓包显示来往的DHCP报文均为广播：

第七步：查看RFC2131可知DHCP ACK报文“broadcast or unicast, based on bootp flags.”综上可知，客户MESH建立异常的现象是由于中继设备DHCP协议实现不标准引起。

使用H3C交换机做中继或者将MAP的DHCP服务器放到AC上通过二层拿地址。