某局点Portal认证用户不定期异常掉线问题分析

据一线反馈，某局点使用iMC EIA进行Portal认证，认证客户端为PC，使用iNode认证。在认证通过后，会不定期收到服务器发送的下线通知导致用户异常下线。

1、根据用户反馈的时间点收集UAM后台调试日志进行分析

% 2016-03-11 09:04:23.966 ; [L_DEBUG (4)] ; [5684] ; LAN ; tianbo ; 1 ; 12ad36526d41425d94495a38b3a171d6 ; (NULL) ; RT[0]: Receive message from 10.46.80.180:
   CODE = 1.\\认证请求报文
    ID   = 206.
    ATTRIBUTES:
    User-Name(1) = "..OGpQTUhaPiN6RkIzdQhzKkXTPEs=  tianbo".
    Password(2) = "$$$".
    NAS-IP-Address(4) = 170807476.
    NAS-Identifier(32) = "WX5510E".
    NAS-Port(5) = 16793772.
    NAS-Port-Id(87) = "0100004000000172".
    NAS-Port-Type(61) = 15.
    Service-Type(6) = 2.
    Framed-Protocol(7) = 255.
    Calling-Station-Id(31) = "24-77-03-00-E6-10".
    Acct-Session-Id(44) = "1160211090221d90".
    Framed-IP-Address(8) = 170830854

Code = 2\\认证回应报文
  ID = 206
  ATTRIBUTES:
  User-Name(1) = ..OGpQTUhaPiN6RkIzdQhzKkXTPEs=  tianbo
  Service_Type(6) = 2
  State(24) = nMf0l7Am
  Termination-Action(29) = 0
  Session-Timeout(27) = 86401
  Acct-Interim-Interval(85) = 600
  hw_User_Notify(61) = 
  IF_PROXY = 0
  IF_DOUBLE_NETCARD = 0
  IF_IE_PROXY = 0
  FRAMED_IP_SET_MODE = 0
  IF_CHECK_MODIFY_MAC = 0
  IF_CHECK_SAME_MAC = 0
  SERVER_VERSION = R003B03D004SP15
  EAD_EVENT_SEQ_ID = nMf0l7Am

% 2016-03-11 09:04:24.008 ; [L_DEBUG (4)] ; [520] ; LAN ; tianbo ; 4 ; 936d14887da742e5b5dfea4bd33dced1 ; (NULL) ; RT[1]: Receive message from 10.46.80.180:
    CODE = 4.
    ID   = 207.
    ATTRIBUTES:
    User-Name(1) = "..OGpQTUhaPiN6RkIzdQhzKkXTPEs=  tianbo".
    NAS-Identifier(32) = "WX5510E".
    NAS-Port(5) = 16793772.
    NAS-Port-Id(87) = "0100004000000172".
    NAS-Port-Type(61) = 15.
    Calling-Station-Id(31) = "24-77-03-00-E6-10".
    Acct-Status-Type(40) = 1.  \\计费开始报文
    Acct-Authentic(45) = 1.
    Acct-Session-Id(44) = "1160211090221d90".\\计费会话ID
    Framed-IP-Address(8) = 170830854.
    NAS-IP-Address(4) = 170807476.
    Event-Timestamp(55) = 1457686946.

% 2016-03-11 09:04:24.008 ; [WARNING (2)] ; [520] ; UAM ; $SYS$ ; (NULL) ; (NULL) ; (NULL) ; [GetProxyType] No domain name.
% 2016-03-11 09:04:24.011 ; [L_DEBUG (4)] ; [16432] ; LAN ; $SYS$ ; (NULL) ; (NULL) ; (NULL) ; Begin ProcLanAcctMsg() .
% 2016-03-11 09:04:24.011 ; [L_DEBUG (4)] ; [16432] ; LAN ; $SYS$ ; (NULL) ; (NULL) ; (NULL) ; chkScenario: (tianbo) user message is NasIP:170807476,NasIpv6:,UserIP:170830854,UserIpv6:,WlanSsid:,AP:WX5510E.

% 2016-03-11 09:04:24.012 ; [L_DEBUG (4)] ; [16432] ; LAN ; $SYS$ ; (NULL) ; (NULL) ; (NULL) ; acctStart: mac is 24:77:03:00:E6:10.
% 2016-03-11 09:04:24.015 ; [WARNING (2)] ; [16432] ; LAN ; $SYS$ ; (NULL) ; (NULL) ; (NULL) ; LanAcctStartProcess: not insert tbl_online because of exceeding authentication lock time.

插入在线表失败，原因为超过了认证锁定时长
% 2016-03-11 09:04:24.016 ; [L_DEBUG (4)] ; [16432] ; CMacRegInfoManager ;  ; (NULL) ; (NULL) ; (NULL) ; updateTerminalStatus: update tbl_mac_regist_info_status done.
% 2016-03-11 09:04:24.016 ; [L_DEBUG (4)] ; [16432] ; UAM ; $SYS$ ; (NULL) ; (NULL) ; (NULL) ; setMacReg: update the terminal status done.
   Code = 5
   ID = 207
   ATTRIBUTES:

2、我们看到，在09:03：23秒时，设备向iMC发来的认证请求报文（即CODE=1），然后iMC马上给设备回应了计费接受报文（即CODE=2），仅仅过了1S，在09:04:24时，设备又向iMC发来计费开始报文，但是注意红色字体,这时候iMC插入在线表失败，原因是超过了认证锁定时长。我们继续分析UAM报文。

% 2016-03-11 09:16:21.446 ; [L_DEBUG (4)] ; [18364] ; LAN ; $SYS$ ; (NULL) ; (NULL) ; (NULL) ; End ProcLanAcctMsg() successfully.
% 2016-03-11 09:16:24.427 ; [L_DEBUG (4)] ; [520] ; LAN ; tianbo ; 4 ; d2d6051ed6624523b51a90fcf874c19a ; (NULL) ; RT[1]: Receive message from 10.46.80.180:
   CODE = 4.\\计费报文
    ID   = 132.
    ATTRIBUTES:
    User-Name(1) = "..OGpQTUhaPiN6RkIzdQhzKkXTPEs=  tianbo".
    NAS-Identifier(32) = "WX5510E".
    NAS-Port(5) = 16793772.
    NAS-Port-Id(87) = "0100004000000172".
    NAS-Port-Type(61) = 15.
    Calling-Station-Id(31) = "24-77-03-00-E6-10".
    Acct-Status-Type(40) = 3.\\计费更新报文
    Acct-Authentic(45) = 1.
    Acct-Session-Id(44) = "1160211090221d90".\\计费会话ID，可以看出和上一个会话是同一个ID
    Framed-IP-Address(8) = 170830854.
    NAS-IP-Address(4) = 170807476.
    Event-Timestamp(55) = 1457687666.
    Acct-Session-Time(46) = 720.
    Acct-Delay-Time(41) = 2.
    Acct-Input-Octets(42) = 487561.
    Acct-Input-Packets(47) = 4247.
    Acct-Output-Octets(43) = 0.
    Acct-Output-Packets(48) = 0.
    Acct-Input-Gigawords(52) = 0.
    Acct-Output-Gigawords(53) = 0.
% 2016-03-11 09:16:24.445 ; [WARNING (2)] ; [17064] ; LAN ; $SYS$ ; (NULL) ; (NULL) ; (NULL) ; Fail to process user accounting update request: E63010: Users using the specified service are offline.

计费更新失败，失败原因为：用户已经下线

% 2016-03-11 09:16:24.445 ; [L_DEBUG (4)] ; [17064] ; LAN ; $SYS$ ; (NULL) ; (NULL) ; (NULL) ; End ProcLanAcctUpdateMsg() successfully
% 2016-03-11 09:16:24.445 ; [L_DEBUG (4)] ; [17064] ; LAN ; $SYS$ ; (NULL) ; (NULL) ; (NULL) ; Begin replyPrivateAttribute(), auth step is 3,AttrPolicyId is -1,DeviceTypeId is 1100
% 2016-03-11 09:16:24.446 ; [L_DEBUG (4)] ; [17064] ; LAN ; $SYS$ ; (NULL) ; (NULL) ; (NULL) ; Call replyPrivateAttribute() successfully.
% 2016-03-11 09:16:24.446 ; [L_DEBUG (4)] ; [17064] ; LAN ; tianbo ; 5 ; d2d6051ed6624523b51a90fcf874c19a ; (null) ; Send message attribut list:
   Code = 5
   ID = 132
   ATTRIBUTES:
   Session-Timeout(27) = 0

% 2016-03-11 09:16:24.446 ; [L_DEBUG (4)] ; [17064] ; LAN ; $SYS$ ; (NULL) ; (NULL) ; (NULL) ; End ProcLanAcctMsg() successfully.
% 2016-03-11 09:16:25.118 ; [L_DEBUG (4)] ; [2820] ; UAM ; $SYS$ ; (NULL) ; (NULL) ; (NULL) ; drop eap resend pkts every 30 secs.
% 2016-03-11 09:16:26.431 ; [L_DEBUG (4)] ; [520] ; LAN ; tianbo ; 4 ; 9a849cb1dd424381bff9360df3c60e9c ; (NULL) ; RT[1]: Receive message from 10.46.80.180:
     CODE = 4.
     ID   = 133.
    ATTRIBUTES:
    User-Name(1) = "..OGpQTUhaPiN6RkIzdQhzKkXTPEs=  tianbo".
    NAS-Identifier(32) = "WX5510E".
    NAS-Port(5) = 16793772.
    NAS-Port-Id(87) = "0100004000000172".
    NAS-Port-Type(61) = 15.
    Calling-Station-Id(31) = "24-77-03-00-E6-10".
    Acct-Status-Type(40) = 2.\\计费停止报文
    Acct-Authentic(45) = 1.
    Acct-Session-Id(44) = "1160211090221d90".
    Framed-IP-Address(8) = 170830854.
    NAS-IP-Address(4) = 170807476.
    Event-Timestamp(55) = 1457687668.
    Acct-Session-Time(46) = 723.
    Acct-Delay-Time(41) = 3.
    Acct-Input-Octets(42) = 488195.
    Acct-Input-Packets(47) = 4251.
    Acct-Output-Octets(43) = 0.
    Acct-Output-Packets(48) = 0.
    Acct-Input-Gigawords(52) = 0.
    Acct-Output-Gigawords(53) = 0.
    Acct-Terminate-Cause(49) = 5. \\SESSION_TIMEOUT，会话时长超时

% 2016-03-11 09:16:26.438 ; [ERROR   (1)] ; [16548] ; LAN ; $SYS$ ; (NULL) ; (NULL) ; (NULL) ; Fail to select tbl_online in LanAcctStopProcess function. Error message : E63050: Repeated account package.

选择在线表失败，错误原因：重复认证报文
% 2016-03-11 09:16:26.439 ; [L_DEBUG (4)] ; [16548] ; LAN ; tianbo ; 5 ; 9a849cb1dd424381bff9360df3c60e9c ; (null) ; Send message attribut list:
   Code = 5
   ID = 133
   ATTRIBUTES:

3、在09:16:21时，设备向iMC发来了计费更新报文，但是注意到，这一次计费更新报文异常提示了E63010: Users using the specified service are offline.而在CODE=5即计费回应报文了ACCT-SESSION-TIME=0。这就导致了设备马上发来了计费停止报文，并且我们看到ACCT-Terminate-Cause=5（会话超时），而特别注意到红色字体提示了选择在线表失败，错误提示为重复认证报文。

4、综上分析，我们知道iMC的在线表是通过计费开始报文插入的，如果在认证锁定时长内计费开始报文没有送达到iMC，即使认证通过在iMC上也看不到该用户的在线信息，而到了下一个计费更新报文到来时，由于计费更新报文会选择该用户的在线表作为更新凭据，既然上一次认证锁定时长内没有成功创建在线表，那么计费更新报文就会更新失败，认为没有该用户的在线信息，从而在计费回应报文（CODE=5）中属性值Acct-Session-Time=0。所以设备凭借上一个计费回应报文中的会话时长马上给iMC发来了计费停止报文。而iMC缺省的认证锁定时长为5S，根据以上分析，我们认证该参数被修改过，从而导致该问题出现

1、经过确认，发现认证锁定时长为1S，修改为5S后问题不再复现。

1、认真分析UAM报文

2、仔细排查iMC的各项配置

3、抓包、收集日志发给二线工程师进行定位。