Avalanche Test unexpected stop: IPsecSA::UpdateIpsecSA SecAssoc 0x3eed588 is already exist!
Hello all,
I'm running an endurance test on a DUT with avalanche. I configured 5 static tunnels on server side and 1 static tunnel on client side. The test seems to work fine except for the fact that it stops running after 8 hours (around). I did 3 tries and I had always the same result. The IPSec tunnels are configured to use IKEv1, if more details are needed please let me know.
Below the output I get from the event log messages:
Event Log Messages: [192.168.181.136:client]:
[0]: [2015/05/19 23:44:38] 192.168.181.136:cpu9: (8803) [Repeat:2] - Current state is:R_Quick_Initial change to next state is:R_Send_Resp.
[0]: [2015/05/19 23:47:30] 192.168.181.136:cpu8: (8812) [Repeat:4] - Current state is:I_Quick_Initial change to next state is:I_Quick_Send_Quick1_Waiting.
[0]: [2015/05/19 23:47:30] 192.168.181.136:cpu9: (8803) [Repeat:1388] - TimeWheel::Add Event on List
[2]: [2015/05/19 23:47:30] 192.168.181.136:cpu9: (8803) Current System Status: free/used/total system memory (MB): 115722/13170/128892 used/total pool memory (MB): 190/7368 malloc/non-malloc used memory (MB): 190/0 malloc/free reference count: 711444/711051 [0]: [2015/05/19 23:52:33] 192.168.181.136:cpu9: (8803) [Repeat:2446] - TimeWheel::Add Event on List
[4]: [2015/05/19 23:52:33] 192.168.181.136:cpu9: (8803) HTTPS::Timeout Error due to Data Timeout
[0]: [2015/05/19 23:53:09] 192.168.181.136:cpu9: (8803) [Repeat:287] - TimeWheel::Add Event on List
[4]: [2015/05/19 23:53:09] 192.168.181.136:cpu9: (8803) HTTPS::Timeout Error due to Data Timeout
[0]: [2015/05/19 23:53:42] 192.168.181.136:cpu9: (8803) [Repeat:267] - TimeWheel::Add Event on List
[4]: [2015/05/19 23:53:42] 192.168.181.136:cpu9: (8803) HTTPS::Timeout Error due to Data Timeout
[0]: [2015/05/19 23:57:32] 192.168.181.136:cpu9: (8803) [Repeat:1856] - TimeWheel::Add Event on List
[4]: [2015/05/19 23:57:33] 192.168.181.136:cpu9: (8803) HTTPS::Timeout Error due to Data Timeout
[0]: [2015/05/20 00:02:14] 192.168.181.136:cpu9: (8803) [Repeat:2272] - TimeWheel::Add Event on List
[4]: [2015/05/20 00:02:15] 192.168.181.136:cpu9: (8803) HTTPS::Timeout Error due to Data Timeout
[0]: [2015/05/20 00:05:05] 192.168.181.136:cpu9: (8803) [Repeat:1380] - TimeWheel::Add Event on List
[0]: [2015/05/20 00:05:06] 192.168.181.136:cpu9: (8803) [Repeat:2] - Current state is:R_Quick_Initial change to next state is:R_Send_Resp.
[0]: [2015/05/20 00:05:06] 192.168.181.136:cpu9: (8803) [Repeat:8] - TimeWheel::Add Event on List
[0]: [2015/05/20 00:05:07] 192.168.181.136:cpu9: (8803) [Repeat:2] - Current state is:R_Quick_Initial change to next state is:R_Send_Resp.
[0]: [2015/05/20 00:05:53] 192.168.181.136:cpu9: (8803) [Repeat:376] - TimeWheel::Add Event on List
[3]: [2015/05/20 00:05:53] 192.168.181.136:cpu9: (8803) IPsecSA::UpdateIpsecSA - SecAssoc 0x3eed588 is already exist!
[0]: [2015/05/20 00:05:59] 192.168.181.136:cpu9: (8803) [Repeat:48] - TimeWheel::Add Event on List
[3]: [2015/05/20 00:05:59] 192.168.181.136:cpu9: (8803) IPsecSA::UpdateIpsecSA - SecAssoc 0x3eeaef0 is already exist!
[0]: [2015/05/20 00:10:05] 192.168.181.136:cpu9: (8803) [Repeat:1980] - TimeWheel::Add Event on List
[2]: [2015/05/20 00:10:05] 192.168.181.136:cpu8: (8812) Current System Status: free/used/total system memory (MB): 115722/13170/128892 used/total pool memory (MB): 229/7368 malloc/non-malloc used memory (MB): 229/0 malloc/free reference count: 712301/710892
[0]: [2015/05/20 00:10:05] 192.168.181.136:cpu9: (8803) [Repeat:2] - Current state is:I_Quick_Initial change to next state is:I_Quick_Send_Quick1_Waiting.
[0]: [2015/05/20 00:10:35] 192.168.181.136:cpu9: (8803) [Repeat:240] - TimeWheel::Add Event on List
[3]: [2015/05/20 00:10:35] 192.168.181.136:cpu9: (8803) IPsecSA::UpdateIpsecSA - SecAssoc 0x35cabc0 is already exist!
[0]: [2015/05/20 00:11:18] 192.168.181.136:cpu9: (8803) [Repeat:352] - TimeWheel::Add Event on List
[4]: [2015/05/20 00:11:18] 192.168.181.136:cpu9: (8803) WR(multi-sa) don't support start IPsecSA rekey. ignore.
[0]: [2015/05/20 00:11:20] 192.168.181.136:cpu9: (8803) [Repeat:16] - TimeWheel::Add Event on List
[0]: [2015/05/20 00:11:20] 192.168.181.136:cpu9: (8803) [Repeat:2] - Current state is:R_Quick_Initial change to next state is:R_Send_Resp.
[0]: [2015/05/20 00:15:58] 192.168.181.136:cpu9: (8803) [Repeat:2244] - TimeWheel::Add Event on List
[4]: [2015/05/20 00:15:59] 192.168.181.136:cpu9: (8803) HTTPS::Timeout Error due to Data Timeout
[0]: [2015/05/20 00:28:45] 192.168.181.136:cpu9: (8803) [Repeat:6180] - TimeWheel::Add Event on List
[4]: [2015/05/20 00:28:46] 192.168.181.136:cpu9: (8803) HTTPS::Timeout Error due to Data Timeout
[0]: [2015/05/20 00:30:07] 192.168.181.136:cpu9: (8803) [Repeat:660] - TimeWheel::Add Event on List
[4]: [2015/05/20 00:30:07] 192.168.181.136:cpu9: (8803) HTTPS::Timeout Error due to Data Timeout
[0]: [2015/05/20 00:32:40] 192.168.181.136:cpu9: (8803) [Repeat:1236] - TimeWheel::Add Event on List
[4]: [2015/05/20 00:32:41] 192.168.181.136:cpu9: (8803) HTTPS::Timeout Error due to Data Timeout
[0]: [2015/05/20 00:34:16] 192.168.181.136:cpu9: (8803) [Repeat:772] - TimeWheel::Add Event on List
[0]: [2015/05/20 00:34:16] 192.168.181.136:cpu9: (8803) [Repeat:2] - Current state is:R_Quick_Initial change to next state is:R_Send_Resp.
[0]: [2015/05/20 00:34:18] 192.168.181.136:cpu9: (8803) [Repeat:12] - TimeWheel::Add Event on List
[0]: [2015/05/20 00:34:18] 192.168.181.136:cpu9: (8803) [Repeat:2] - Current state is:R_Quick_Initial change to next state is:R_Send_Resp.
[0]: [2015/05/20 00:35:05] 192.168.181.136:cpu9: (8803) [Repeat:380] - TimeWheel::Add Event on List
[3]: [2015/05/20 00:35:05] 192.168.181.136:cpu9: (8803) IPsecSA::UpdateIpsecSA - SecAssoc 0x35c8ce0 is already exist!
[0]: [2015/05/20 00:35:06] 192.168.181.136:cpu9: (8803) [Repeat:8] - TimeWheel::Add Event on List
[3]: [2015/05/20 00:35:06] 192.168.181.136:cpu9: (8803) IPsecSA::UpdateIpsecSA - SecAssoc 0x35c8048 is already exist!
[0]: [2015/05/20 00:39:35] 192.168.181.136:cpu9: (8803) [Repeat:2168] - TimeWheel::Add Event on List
[0]: [2015/05/20 00:39:35] 192.168.181.136:cpu9: (8803) [Repeat:2] - Current state is:I_Quick_Initial change to next state is:I_Quick_Send_Quick1_Waiting.
[0]: [2015/05/20 00:40:05] 192.168.181.136:cpu9: (8803) [Repeat:240] - TimeWheel::Add Event on List
[3]: [2015/05/20 00:40:05] 192.168.181.136:cpu9: (8803) IPsecSA::UpdateIpsecSA - SecAssoc 0x3eeac18 is already exist!
[0]: [2015/05/20 00:40:50] 192.168.181.136:cpu9: (8803) [Repeat:368] - TimeWheel::Add Event on List
[4]: [2015/05/20 00:40:50] 192.168.181.136:cpu9: (8803) WR(multi-sa) don't support start IPsecSA rekey. ignore.
[0]: [2015/05/20 00:40:57] 192.168.181.136:cpu9: (8803) [Repeat:56] - TimeWheel::Add Event on List
[0]: [2015/05/20 00:40:57] 192.168.181.136:cpu9: (8803) [Repeat:2] - Current state is:R_Quick_Initial change to next state is:R_Send_Resp.
[0]: [2015/05/20 00:42:28] 192.168.181.136:cpu9: (8803) [Repeat:736] - TimeWheel::Add Event on List
[0]: [2015/05/20 00:42:29] 192.168.181.136:cpu9: (8803) [Repeat:6] - Current state is:R_Main_Initial change to next state is:R_Send_SA_Waiting_Req.
[0]: [2015/05/20 00:42:33] 192.168.181.136:cpu9: (8803) [Repeat:36] - TimeWheel::Add Event on List
[0]: [2015/05/20 00:42:33] 192.168.181.136:cpu9: (8803) [Repeat:12] - Current state is:R_Main_Initial change to next state is:R_Send_SA_Waiting_Req.
[0]: [2015/05/20 00:43:03] 192.168.181.136:cpu8: (8812) [Repeat:4] - Current state is:I_Quick_Initial change to next state is:I_Quick_Send_Quick1_Waiting.
[0]: [2015/05/20 00:44:07] 192.168.181.136:cpu9: (8803) [Repeat:760] - TimeWheel::Add Event on List
[4]: [2015/05/20 00:44:07] 192.168.181.136:cpu9: (8803) WR(multi-sa) don't support start IPsecSA rekey. ignore.
[0]: [2015/05/20 00:44:13] 192.168.181.136:cpu9: (8803) [Repeat:48] - TimeWheel::Add Event on List
[0]: [2015/05/20 00:44:13] 192.168.181.136:cpu9: (8803) [Repeat:2] - Current state is:R_Quick_Initial change to next state is:R_Send_Resp.
[0]: [2015/05/20 00:47:05] 192.168.181.136:cpu9: (8803) [Repeat:1384] - TimeWheel::Add Event on List
[0]: [2015/05/20 00:47:05] 192.168.181.136:cpu9: (8803) IPsecIkeTunnel::CreateIPsecSA - Multi IPSec SA!
[0]: [2015/05/20 00:47:05] 192.168.181.136:cpu9: (8803) Current state is:I_Quick_Initial change to next state is:I_Quick_Send_Quick1_Waiting.
[0]: [2015/05/20 00:47:08] 192.168.181.136:cpu9: (8803) [Repeat:24] - TimeWheel::Add Event on List
[0]: [2015/05/20 00:47:08] 192.168.181.136:cpu9: (8803) IPsecIkeTunnel::CreateIPsecSA - Multi IPSec SA!
[0]: [2015/05/20 00:47:08] 192.168.181.136:cpu9: (8803) [Repeat:2] - Current state is:R_Quick_Initial change to next state is:R_Send_Resp.
[0]: [2015/05/20 00:47:09] 192.168.181.136:cpu9: (8803) [Repeat:8] - TimeWheel::Add Event on List
[0]: [2015/05/20 00:47:09] 192.168.181.136:cpu9: (8803) IPsecIkeTunnel::CreateIPsecSA - Multi IPSec SA!
[0]: [2015/05/20 00:47:09] 192.168.181.136:cpu9: (8803) [Repeat:2] - Current state is:R_Quick_Initial change to next state is:R_Send_Resp.
[0]: [2015/05/20 00:47:10] 192.168.181.136:cpu9: (8803) [Repeat:8] - TimeWheel::Add Event on List
[0]: [2015/05/20 00:47:10] 192.168.181.136:cpu9: (8803) IkeV1::SaReTxTimeOut():ReTx time out happens, mRetriedTimes:0 , timeout:5.
[0]: [2015/05/20 00:47:20] 192.168.181.136:cpu9: (8803) [Repeat:80] - TimeWheel::Add Event on List
[0]: [2015/05/20 00:47:20] 192.168.181.136:cpu9: (8803) IkeV1::SaReTxTimeOut():ReTx time out happens, mRetriedTimes:1 , timeout:5.
[0]: [2015/05/20 00:47:30] 192.168.181.136:cpu8: (8812) [Repeat:3] - Current state is:R_Main_Initial change to next state is:R_Send_SA_Waiting_Req.
[0]: [2015/05/20 00:47:30] 192.168.181.136:cpu9: (8803) [Repeat:84] - TimeWheel::Add Event on List
[2]: [2015/05/20 00:47:30] 192.168.181.136:cpu9: (8803) Current System Status: free/used/total system memory (MB): 115718/13174/128892 used/total pool memory (MB): 190/7368 malloc/non-malloc used memory (MB): 190/0 malloc/free reference count: 812998/812605
[0]: [2015/05/20 00:47:33] 192.168.181.136:cpu9: (8803) [Repeat:24] - TimeWheel::Add Event on List
[4]: [2015/05/20 00:47:33] 192.168.181.136:cpu9: (8803) (log1)SIGSEGV received, aborting.
[4]: [2015/05/20 00:47:33] 192.168.181.136:cpu9: (8803) Segfault trace : 0x00407AC0 0x0149B740 0x0064C087 0x00890C06 0x008A17FB 0x008E681A 0x008E6C4E 0x008C180C 0x008C0B6C 0x0064C830 0x0064DB20 0x005FB151 0x005FADBD 0x005E1A4C 0x0064982C 0x006B082A 0x0042CB54 0x00416817 0x00416545 0x0040B1C8 [4]: [2015/05/20 00:47:33] 192.168.181.136:cpu9: (8803) SIGSEGV handler done, exiting.
[1]: [2015/05/20 00:47:39] Unit 0: stopping test
[2]: [2015/05/20 00:47:39] 192.168.181.136:cpu8: (8812) Current System Status: free/used/total system memory (MB): 115718/13174/128892 used/total pool memory (MB): 229/7368 malloc/non-malloc used memory (MB): 229/0 malloc/free reference count: 813828/812419
[2]: [2015/05/20 00:47:39] 192.168.181.136:cpu8: (8812) Stop Signal received at stage 0!
[2]: [2015/05/20 00:47:39] Unit 0: aborting test [1]: [2015/05/20 00:47:39] 192.168.181.136:cpu8: (8812) [Repeat:11] - Stop button depress received.
[2]: [2015/05/20 00:47:39] 192.168.181.136:cpu8: (8812) Stop Signal received at stage 1!
[1]: [2015/05/20 00:47:39] 192.168.181.136:cpu8: (8812) Stop button depress received.
[3]: [2015/05/20 00:47:39] 192.168.181.136:cpu8: (8812) Entering RampDown phase
[2]: [2015/05/20 00:47:39] 192.168.181.136:cpu8: (8812) Test soak_FFM_0_2 ended
[2]: [2015/05/20 00:47:39] 192.168.181.136:cpu8: (8812) TCP Packets received: 56321636, Incoming packets not processed by TCP: unknown address/port 1090, out of sequence 10740790, duplicate 12
[1]: [2015/05/20 00:47:39] 192.168.181.136:cpu8: (8812) returned from executeWA()
[1]: [2015/05/20 00:47:39] 192.168.181.136:cpu8: (8812) WawrInit::Init() completed
[2]: [2015/05/20 00:47:39] 192.168.181.136:cpu8: (8812) ***** End of main ***** Current System Status: free/used/total system memory (MB): 116068/12824/128892 used/total pool memory (MB): 14/7368 malloc/non-malloc used memory (MB): 14/0 malloc/free reference count: 813959/813902
[1]: [2015/05/20 00:47:39] 192.168.181.136:cpu8: (8812) ***** End of main *****
Thanks a lot for any suggestion!
Alberto
Just a note, 8 hours (28800 sec) is the phase one re-key timer
