Debug 2011-04-21T03:59:26 Process=iked msg=******** RECV an IKE packet at 100.100.100.37:500(socket=11 ifIndex=2) from Peer 100.100.100.38:75 ******** Debug 2011-04-21T03:59:26 Process=iked msg=IkeFindIsakmpPolicy: --> Debug 2011-04-21T03:59:26 Process=iked msg=ike_match_if_name: Match pcy [T1 Mobile VPN IPSec_mu] dev=anyE, pkt if[2]=eth0 Debug 2011-04-21T03:59:26 Process=iked msg=Found IKE Policy [T1 Mobile VPN IPSec_mu, dev=anyE] for peer IP=100.100.100.38, numXform=1, pkt ifIndex=2 Debug 2011-04-21T03:59:26 Process=iked msg=IKE Policy details: 1th xform: grp=1 auth=1 encrypt=5 hash=2 lifeTime=28800 lifeKB=0 Debug 2011-04-21T03:59:26 Process=iked msg=IkeFindIsakmpPolicy: <-- Debug 2011-04-21T03:59:26 Process=iked msg=IkeFindIsakmpPolicyAmProxyID: --> Debug 2011-04-21T03:59:26 Process=iked msg=peer ID type 3 length 19 data0 54 Debug 2011-04-21T03:59:26 Process=iked msg=Matching proxy_id: pcy [T1 Mobile VPN IPSec_mu] mask=8, Peer ID type=3 len=19 Data0=54 Debug 2011-04-21T03:59:26 Process=iked msg=Searching ID: user domain - myData [T1 Mobile VPN IPSec] peerId [T1 Mobile VPN IPSec] Debug 2011-04-21T03:59:26 Process=iked msg=ike_match_if_name: Match pcy [T1 Mobile VPN IPSec_mu] dev=anyE, pkt if[2]=eth0 Debug 2011-04-21T03:59:26 Process=iked msg=AggrMode: match addr|ID|if pcy [T1 Mobile VPN IPSec_mu] if=2, peer 100.100.100.38 Debug 2011-04-21T03:59:26 Process=iked msg=IkeFindIsakmpPolicyAmProxyID: <-- Debug 2011-04-21T03:59:26 Process=iked msg=After id match, use IKE Policy [T1 Mobile VPN IPSec_mu, dev=anyE] for peer IP=100.100.100.38, numXform=1, pkt ifIndex=2 Debug 2011-04-21T03:59:26 Process=iked msg=IkeCreateIsakmpSA: init vpnDpdSequenceNum = 464974783(Isakmp SA 0x187628) Debug 2011-04-21T03:59:26 Process=iked msg=AggrMode: recv 1st msg pcy [T1 Mobile VPN IPSec_mu] peer 100.100.100.38:75 (Ct=6) Debug 2011-04-21T03:59:26 Process=iked msg=Phase 1 started by peer with policy [T1 Mobile VPN IPSec_mu] from 100.100.100.38:75 aggressive mode Debug 2011-04-21T03:59:26 Process=iked msg=IkeCheckPayloads : Payload(SA) Len(56) Debug 2011-04-21T03:59:26 Process=iked msg=IkeCheckPayloadsG: Payload(4) Len(100) Debug 2011-04-21T03:59:26 Process=iked msg=IkeCheckPayloadsG: Payload(10) Len(24) Debug 2011-04-21T03:59:26 Process=iked msg=IkeCheckPayloadsG: Payload(5) Len(27) Debug 2011-04-21T03:59:26 Process=iked msg=IkeCheckPayloadsG: Payload(13) Len(12) Debug 2011-04-21T03:59:26 Process=iked msg=IkeCheckPayloadsG: Payload(13) Len(20) Debug 2011-04-21T03:59:26 Process=iked msg=IkeCheckPayloadsG: Payload(13) Len(20) Debug 2011-04-21T03:59:26 Process=iked msg=IkeCheckPayloadsG: Payload(13) Len(20) Debug 2011-04-21T03:59:26 Process=iked msg=IkeCheckPayloadsG: Payload(13) Len(20) Debug 2011-04-21T03:59:26 Process=iked msg=IkeCheckPayloadsG: Payload(13) Len(20) Debug 2011-04-21T03:59:26 Process=iked msg=IkeCheckPayloadsG: Payload(13) Len(20) Debug 2011-04-21T03:59:26 Process=iked msg=IkeCheckPayloadsG: Payload(13) Len(20) Debug 2011-04-21T03:59:26 Process=iked msg=IkeCheckPayloadsG: Payload(13) Len(20) Debug 2011-04-21T03:59:26 Process=iked msg=IkeCheckPayloadsG: Payload(13) Len(24) Debug 2011-04-21T03:59:26 Process=iked msg=IkeCheckPayloadsG: Payload(13) Len(20) Debug 2011-04-21T03:59:26 Process=iked msg=IkeCheckPayloadsG: Payload(13) Len(20) Debug 2011-04-21T03:59:26 Process=iked msg=IkeProposalNtoH : Recv SPI(0000 0000 0000 0x24) SPI(0000 0000 0000 0000) Debug 2011-04-21T03:59:26 Process=iked msg=IkeXformNtoH (AES) : numAttribs 6 Debug 2011-04-21T03:59:26 Process=iked msg=IKE Proposal : peer propose EncryptAlgo 3DES Debug 2011-04-21T03:59:26 Process=iked msg=IKE Proposal : peer propose AuthAlgo SHA-1 Debug 2011-04-21T03:59:26 Process=iked msg=Select IKE Proposal : matched DHGrp 1 Debug 2011-04-21T03:59:26 Process=iked msg=IKE Proposal : peer propose XAuthMode 65001 Debug 2011-04-21T03:59:26 Process=iked msg=P1__Mode: XAuth enforced, peer propose 65001 Debug 2011-04-21T03:59:26 Process=iked msg=IkeSelect Xauth= 65001 1 Debug 2011-04-21T03:59:26 Process=iked msg=Select Proposal : peer propose life sec 86400 Debug 2011-04-21T03:59:26 Process=iked msg=Select Proposal : take local proposed life sec 28800 Debug 2011-04-21T03:59:26 Process=iked msg=IkeProposalHtoN : net order spi(0000 0000 0000 0000) Debug 2011-04-21T03:59:26 Process=iked msg=peer ID type 3 length 19 data0 54 Debug 2011-04-21T03:59:26 Process=iked msg=Process ID Payload: IdBodySize 23, IdType 3, IdBody 3 0 0 0 Debug 2011-04-21T03:59:26 Process=iked msg=Received VID_PAYLOAD - VPN_XAUTH06_VID(first 4bytes: 0x09002689) Debug 2011-04-21T03:59:26 Process=iked msg=IkeProcessPayloads : VID_PAYLOAD (first 4bytes: 0x4485152d) Debug 2011-04-21T03:59:26 Process=iked msg=IkeProcessPayloads : VID_PAYLOAD (first 4bytes: 0x16f6ca16) Debug 2011-04-21T03:59:26 Process=iked msg=IkeProcessPayloads : VID_PAYLOAD (first 4bytes: 0x90cb8091) Debug 2011-04-21T03:59:26 Process=iked msg=Received VID_PAYLOAD - VPN_NAT-T_VID(first 4bytes: 0x9180cb90) Debug 2011-04-21T03:59:26 Process=iked msg=Use IKE Policy[T1 Mobile VPN IPSec_mu] Debug 2011-04-21T03:59:26 Process=iked msg=P1__Mode: NAT-T negotiated [T1 Mobile VPN IPSec_mu] peer 0x18adb226:75 Debug 2011-04-21T03:59:26 Process=iked msg=IkeProcessPayloads : VID_PAYLOAD (first 4bytes: 0x7d9419a6) Debug 2011-04-21T03:59:26 Process=iked msg=IkeProcessPayloads : VID_PAYLOAD (first 4bytes: 0x4a131c81) Debug 2011-04-21T03:59:26 Process=iked msg=Received VID_PAYLOAD - VPN_DPD_VID(first 4bytes: 0xafcad713) Debug 2011-04-21T03:59:26 Process=iked msg=Enable DPD locally Debug 2011-04-21T03:59:26 Process=iked msg=IkeProcessPayloads : VID_PAYLOAD (first 4bytes: 0x3b9031dc) Debug 2011-04-21T03:59:26 Process=iked msg=IkeProcessPayloads : VID_PAYLOAD (first 4bytes: 0xf14b94b7) Debug 2011-04-21T03:59:26 Process=iked msg=IkeProcessPayloads : VID_PAYLOAD (first 4bytes: 0x166f932d) Debug 2011-04-21T03:59:26 Process=iked msg=IkeProcessPayloads : VID_PAYLOAD (first 4bytes: 0x8404adf9) Debug 2011-04-21T03:59:26 Process=iked msg=IkeProcessPayloads : VID_PAYLOAD (first 4bytes: 0x12f5f28c) Debug 2011-04-21T03:59:26 Process=iked msg=Use IKE Policy[T1 Mobile VPN IPSec_mu] Debug 2011-04-21T03:59:26 Process=iked msg=AggrMode: >>2nd PSK ID type 1 len 4 data0-3 18 ad b2 25 Debug 2011-04-21T03:59:26 Process=iked msg=IkeAMConstructSAMsg: (VID opt) KeepAlive=0, NatTNegotiated=2, VLClient=0, DPD=1 Debug 2011-04-21T03:59:26 Process=iked msg=AggrMode: add VPN IKE DPD VID (sz 20) Debug 2011-04-21T03:59:26 Process=iked msg=(NATT)IkeGetNatDHash: SHA HASH Data 000077d1 b8c23371 5325193f 76658fd7 Debug 2011-04-21T03:59:26 Process=iked msg=(NATT)IkeGetNatDHash: SHA HASH Data 00005215 d7425e40 0f027408 4e3ce77d Debug 2011-04-21T03:59:26 Process=iked msg=IkeAMConstructSAMsg: (Done) TotalLen 236 IdSize 12 CertSize 0 SigSize 0 CertReqSize 0, DpdSize=20, KaliveSize=0 ulNatTSize=20, ulNatDSize=48, ulVLSize=0 Debug 2011-04-21T03:59:26 Process=iked msg= Sending second message with policy [T1 Mobile VPN IPSec_mu] to 100.100.100.38:75 aggressive mode Debug 2011-04-21T03:59:26 Process=iked msg=******** RECV an IKE packet at 100.100.100.37:4500(socket=12 ifIndex=2) from Peer 100.100.100.38:10068 ******** Debug 2011-04-21T03:59:26 Process=iked msg=IkeFindIsakmpPolicy: --> Debug 2011-04-21T03:59:26 Process=iked msg=ike_match_if_name: Match pcy [T1 Mobile VPN IPSec_mu] dev=anyE, pkt if[2]=eth0 Debug 2011-04-21T03:59:26 Process=iked msg=Found IKE Policy [T1 Mobile VPN IPSec_mu, dev=anyE] for peer IP=100.100.100.38, numXform=1, pkt ifIndex=2 Debug 2011-04-21T03:59:26 Process=iked msg=IKE Policy details: 1th xform: grp=1 auth=1 encrypt=5 hash=2 lifeTime=28800 lifeKB=0 Debug 2011-04-21T03:59:26 Process=iked msg=IkeFindIsakmpPolicy: <-- Debug 2011-04-21T03:59:26 Process=iked msg=(NATT)Process IKE Packet : Skip non_esp_marker Debug 2011-04-21T03:59:26 Process=iked msg=Use IKE Policy[T1 Mobile VPN IPSec_mu] Debug 2011-04-21T03:59:26 Process=iked msg=Received third message with policy [T1 Mobile VPN IPSec_mu] from 100.100.100.38:10068 aggressive mode Debug 2011-04-21T03:59:26 Process=iked msg=IkeCheckPayloads : Payload(HASH) Len(10583) Debug 2011-04-21T03:59:26 Process=iked msg=Check Payloads : HASH illegal payload length! size=10583 total=10583 Debug 2011-04-21T03:59:26 Process=iked msg=IkeAMProcessHashMsg : IkeCheckPayloads failed Debug 2011-04-21T03:59:26 Process=iked msg=Process 3rd Msg (AM): failed to process hash payload Debug 2011-04-21T03:59:26 Process=iked msg=Cannot process AG HASH payload from 100.100.100.38:10068 to 100.100.100.37 cookies i=f4cbb379 7514e0ed r=566c689b d8d582b7 Debug 2011-04-21T03:59:26 Process=iked msg=ike_process_pkt : ProcessData returned error (-1) Debug 2011-04-21T03:59:26 Process=iked msg=******** RECV an IKE packet at 100.100.100.37:4500(socket=12 ifIndex=2) from Peer 100.100.100.38:10068 ******** Debug 2011-04-21T03:59:26 Process=iked msg=IkeFindIsakmpPolicy: --> Debug 2011-04-21T03:59:26 Process=iked msg=ike_match_if_name: Match pcy [T1 Mobile VPN IPSec_mu] dev=anyE, pkt if[2]=eth0 Debug 2011-04-21T03:59:26 Process=iked msg=Found IKE Policy [T1 Mobile VPN IPSec_mu, dev=anyE] for peer IP=100.100.100.38, numXform=1, pkt ifIndex=2 Debug 2011-04-21T03:59:26 Process=iked msg=IKE Policy details: 1th xform: grp=1 auth=1 encrypt=5 hash=2 lifeTime=28800 lifeKB=0 Debug 2011-04-21T03:59:26 Process=iked msg=IkeFindIsakmpPolicy: <-- Debug 2011-04-21T03:59:26 Process=iked msg=(NATT)Process IKE Packet : Skip non_esp_marker Debug 2011-04-21T03:59:26 Process=iked msg=Use IKE Policy[T1 Mobile VPN IPSec_mu] Debug 2011-04-21T03:59:26 Process=iked msg=Process INFO_EXCHANGE : EncryptBit set before SA created Debug 2011-04-21T03:59:26 Process=iked msg=Cannot process the inform message from 100.100.100.38:10068 to 100.100.100.37 cookies i=f4cbb379 7514e0ed r=566c689b d8d582b7 Debug 2011-04-21T03:59:27 Process=iked msg=ike_process_pkt : ProcessData returned error (-1) Debug 2011-04-21T03:59:29 Process=sessiond msg=OK! Sent out wgapi msg xpath=/toSessionClient/checkActivity, dstIPCAddr=400744 Debug 2011-04-21T03:59:29 Process=sessiond msg=updateSession: role 0, enable 0, state 1 Debug 2011-04-21T03:59:29 Process=sessiond msg=sessiond: sessiond WGAPI call Debug 2011-04-21T03:59:29 Process=sessiond msg=sessiond: wgapi: rcved cmd=1 '/toSessiond/updateActivity' fromIPC=4196164 serial=0000000000000 Debug 2011-04-21T03:59:29 Process=iked msg=sendto_with_pktinfo: sendmsg with MARKER via fd=12, DestPort=10068 SrcPort=4500 Debug 2011-04-21T03:59:29 Process=sessiond msg=OK! sess update oK, sessId=5 Debug 2011-04-21T03:59:29 Process=iked msg=IkeRetryTimeout :: Retrying 1st phase.. Debug 2011-04-21T03:59:29 Process=sessiond msg=sessiond: get into sess_prcs_status(): xpath=/toSessiond/updateActivity Debug 2011-04-21T03:59:31 Process=iked msg=******** RECV message on fd_server(7) ******** Debug 2011-04-21T03:59:31 Process=iked msg=RECV cmd=7, xpath=/ping (status:1, action:2, notification:5, wgcmd:7) Debug 2011-04-21T03:59:31 Process=sessiond msg=sessiond: sessiond WGAPI call Debug 2011-04-21T03:59:31 Process=sessiond msg=sessiond: wgapi: rcved cmd=7 '/ping' fromIPC=1858 serial=0000000000000 Debug 2011-04-21T03:59:32 Process=iked msg=IkeRetryTimeout :: Retrying 1st phase.. Debug 2011-04-21T03:59:32 Process=iked msg=sendto_with_pktinfo: sendmsg with MARKER via fd=12, DestPort=10068 SrcPort=4500 Debug 2011-04-21T03:59:35 Process=iked msg=IkeRetryTimeout :: Retrying 1st phase.. Debug 2011-04-21T03:59:35 Process=iked msg=sendto_with_pktinfo: sendmsg with MARKER via fd=12, DestPort=10068 SrcPort=4500 Debug 2011-04-21T03:59:38 Process=iked msg=(Delete P1SA) maxPendingP2SARequest 128 current 0 Debug 2011-04-21T03:59:38 Process=iked msg=Drop negotiation to peer 100.100.100.38:10068 due to phase 1 retry timeout Debug 2011-04-21T03:59:38 Process=iked msg=ike_p1_status_chg: ikePcyName=T1 Mobile VPN IPSec_mu, status=DOWN Debug 2011-04-21T03:59:38 Process=iked msg=ike_p1_status_chg: Clearing connectP1.peerIp for dynamic host Debug 2011-04-21T03:59:38 Process=iked msg=ikeMultiWanVpnFailOver: --> Debug 2011-04-21T03:59:38 Process=iked msg=ikeMultiWanVpnFailOver: MWAN no need to do failover for muvpn case(ikePcyName=T1 Mobile VPN IPSec_mu, vpntype=2) Debug 2011-04-21T03:59:38 Process=iked msg=IkeDeleteIsakmpSA: try to delete Isakmp SA 0x187628 Debug 2011-04-21T03:59:38 Process=iked msg=Totally 0 Pending P2 SA Requests Got Dropped. Debug 2011-04-21T03:59:38 Process=iked msg=IkeDeleteIsakmpSA: Stop Phase One Retry and Life Timer Debug 2011-04-21T03:59:38 Process=iked msg=IkeDeleteIsakmpSA: Stop Phase One DPD Retry timer Debug 2011-04-21T03:59:38 Process=iked msg=Use IKE Policy[T1 Mobile VPN IPSec_mu] Debug 2011-04-21T03:59:38 Process=iked msg=IkeDeleteIsakmpSA: found it, remove IkeSA 187628 from IkePolicy Debug 2011-04-21T03:59:38 Process=iked msg=IkeDeleteIsakmpSA: from pcy list, P1SANum created 0, active 0 Debug 2011-04-21T03:59:38 Process=iked msg=IkeDropIkeSAByAddr: delete IkeSA from peerTable idx 37 peer1 0x18adb225 peer2 0x18adb226 Debug 2011-04-21T03:59:38 Process=iked msg=(Delete P1SA) rasUserCapacity 5 count 0 Debug 2011-04-21T03:59:38 Process=iked msg=Phase 1 IkeRetryTimeout: IsakmpSA NOT Matured