question

acappadonia avatar image
acappadonia asked acappadonia commented

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

Avalancheipsec
1 comment
10 |950

Up to 2 attachments (including images) can be used with a maximum of 512.0 KiB each and 1.0 MiB total.

acappadonia avatar image acappadonia commented ·

Just a note, 8 hours (28800 sec) is the phase one re-key timer

0 Likes 0 ·

0 Answers

·

Write an Answer

Hint: Notify or tag a user in this post by typing @username.

Up to 2 attachments (including images) can be used with a maximum of 512.0 KiB each and 1.0 MiB total.