[strongSwan] Syslog filled with querying SAD entry with SPI nnnnnn failed: No such process (3)

Thu Sep 6 11:08:13 CEST 2012

Hi all ,

I am getting the below traces in my syslogs :

Sep  5 16:08:19 charon: 02[KNL] creating rekey job for ESP CHILD_SA with
SPI c6739a46 and reqid {1}
Sep  5 16:08:19 charon: 02[KNL] creating rekey job for ESP CHILD_SA with
SPI 109d7b5d and reqid {1}
Sep  5 16:08:19 charon: 12[IKE] establishing CHILD_SA tun1_sa1{1}
Sep  5 16:08:19 charon: 12[IKE] establishing CHILD_SA tun1_sa1{1}
Sep  5 16:08:19 charon: 12[ENC] generating CREATE_CHILD_SA request 463 [
N(REKEY_SA) SA No TSi TSr ]
Sep  5 16:08:19 charon: 07[ENC] parsed CREATE_CHILD_SA response 463 [ SA No
TSi TSr ]
Sep  5 16:08:19 charon: 07[IKE] CHILD_SA tun1_sa1{1} established with SPIs
c6e06227_i 109d9f65_o and TS 10.2.4.115/32 === 10.13.125.62/32
10.250.232.249/32 82.79.62.0/24 10.250.30.0/26 10.2.0.0/16 10.13.126.34/32
10.13.126.35/32
Sep  5 16:08:19 charon: 07[IKE] CHILD_SA tun1_sa1{1} established with SPIs
c6e06227_i 109d9f65_o and TS 10.2.4.115/32 === 10.13.125.62/32
10.250.232.249/32 82.79.62.0/24 10.250.30.0/26 10.2.0.0/16 10.13.126.34/32
10.13.126.35/32
Sep  5 16:08:19 charon: 07[IKE] closing CHILD_SA tun1_sa1{1} with SPIs
c6739a46_i (12422310 bytes) 109d7b5d_o (11944303 bytes) and TS 10.2.4.115/32===
10.13.125.62/32 10.250.232.249/32 10.250.30.6/32 10.250.30.10/32
10.250.30.14/32 10.250.30.18/32 10
Sep  5 16:08:19 charon: 07[IKE] closing CHILD_SA tun1_sa1{1} with SPIs
c6739a46_i (12422310 bytes) 109d7b5d_o (11944303 bytes) and TS 10.2.4.115/32===
10.13.125.62/32 10.250.232.249/32 10.250.30.6/32 10.250.30.10/32
10.250.30.14/32 10.250.30.18/32 10
Sep  5 16:08:19 charon: 07[ENC] generating INFORMATIONAL request 464 [ D ]
Sep  5 16:08:19 charon: 10[IKE] establishing CHILD_SA tun1_sa1{1}
Sep  5 16:08:19 charon: 10[IKE] establishing CHILD_SA tun1_sa1{1}
Sep  5 16:08:19 charon: 10[ENC] generating CREATE_CHILD_SA request 465 [
N(REKEY_SA) SA No TSi TSr ]
Sep  5 16:08:20 charon: 04[ENC] parsed CREATE_CHILD_SA response 465 [ SA No
TSi TSr ]
Sep  5 16:08:20 charon: 04[IKE] CHILD_SA tun1_sa1{1} established with SPIs
c02a1e65_i 109d9f66_o and TS 10.2.4.115/32 === 10.13.125.62/32
10.250.232.249/32 82.79.62.0/24 10.250.30.0/26 10.2.0.0/16 10.13.126.34/32
10.13.126.35/32
Sep  5 16:08:20 charon: 04[IKE] CHILD_SA tun1_sa1{1} established with SPIs
c02a1e65_i 109d9f66_o and TS 10.2.4.115/32 === 10.13.125.62/32
10.250.232.249/32 82.79.62.0/24 10.250.30.0/26 10.2.0.0/16 10.13.126.34/32
10.13.126.35/32
Sep  5 16:08:20 charon: 04[IKE] closing CHILD_SA tun1_sa1{1} with SPIs
c6739a46_i (12423135 bytes) 109d7b5d_o (11944303 bytes) and TS 10.2.4.115/32===
10.13.125.62/32 10.250.232.249/32 10.250.30.6/32 10.250.30.10/32
10.250.30.14/32 10.250.30.18/32 10
Sep  5 16:08:20 charon: 04[IKE] closing CHILD_SA tun1_sa1{1} with SPIs
c6739a46_i (12423135 bytes) 109d7b5d_o (11944303 bytes) and TS 10.2.4.115/32===
10.13.125.62/32 10.250.232.249/32 10.250.30.6/32 10.250.30.10/32
10.250.30.14/32 10.250.30.18/32 10
Sep  5 16:08:20 charon: 04[ENC] generating INFORMATIONAL request 466 [ D ]
*Sep  5 16:08:28 charon: 14[ENC] parsed INFORMATIONAL request 0 [ D ]*
Sep  5 16:08:28 charon: 14[IKE] closing CHILD_SA tun1_sa1{1} with SPIs
c6e06227_i *(0 bytes) *109d9f65_o (98 bytes) and TS 10.2.4.115/32 ===
10.13.125.62/32 10.250.232.249/32 82.79.62.0/24 10.250.30.0/26 10.2.0.0/16
10.13.126.34/32 10.13.126.35/32
Sep  5 16:08:28 charon: 14[IKE] closing CHILD_SA tun1_sa1{1} with SPIs
c6e06227_i (0 bytes) 109d9f65_o (98 bytes) and TS 10.2.4.115/32 ===
10.13.125.62/32 10.250.232.249/32 82.79.62.0/24 10.250.30.0/26 10.2.0.0/16
10.13.126.34/32 10.13.126.35/32
Sep  5 16:08:29 ikem_updown.vx:
/vobs/fbsr_plat/ikem/updown/src/ikem_updown.cc:82/buildIKEM_TunnelNotificationBody_t
pid=29379 PLUTO_CONNECTION=tun1_sa1 PLUTO_REQID=1 PLUTO_VERB=down-client
Sep  5 16:08:29 ikem_updown.vx:
/vobs/fbsr_plat/ikem/updown/src/ikem_updown.cc:84/buildIKEM_TunnelNotificationBody_t
pid=29379 PLUTO_MY_SOURCEIP=10.2.4.115 PLUTO_ME=26.0.31.253
PLUTO_PEER=10.209.4.1
*Sep  5 16:08:29 charon: 14[ENC] generating INFORMATIONAL response 0 [ D ]*
Sep  5 16:15:01 crond[853]: USER root pid 30155 cmd /bin/nice -n 19
/opt/alu/fbsr/app/scripts/fsSpaceMonitor
Sep  5 16:15:02 fsSpaceMonitor: run at Wed Sep  5 16:15:02 EEST 2012
Sep  5 16:15:02 fsSpaceMonitor: /mnt/mainfs utilisation is 26% limit is 95%
Sep  5 16:18:47 charon: 02[KNL] creating delete job for ESP CHILD_SA with
SPI c6739a46 and reqid {1}
Sep  5 16:18:47 charon: 02[KNL] creating delete job for ESP CHILD_SA with
SPI 109d7b5d and reqid {1}
Sep  5 16:18:47 charon: 15[KNL] querying SAD entry with SPI c6739a46
failed: No such process (3)
Sep  5 16:18:47 charon: 15[KNL] querying SAD entry with SPI 109d7b5d
failed: No such process (3)
Sep  5 16:18:47 charon: 15[IKE] closing CHILD_SA tun1_sa1{1} with SPIs
c6739a46_i (12524353 bytes) 109d7b5d_o (11944303 bytes) and TS 10.2.4.115/32===
10.13.125.62/32 10.250.232.249/32 10.250.30.6/32 10.250.30.10/32
10.250.30.14/32 10.250.30.18/32 10
Sep  5 16:18:47 charon: 15[IKE] closing CHILD_SA tun1_sa1{1} with SPIs
c6739a46_i (12524353 bytes) 109d7b5d_o (11944303 bytes) and TS 10.2.4.115/32===
10.13.125.62/32 10.250.232.249/32 10.250.30.6/32 10.250.30.10/32
10.250.30.14/32 10.250.30.18/32 10
Sep  5 16:18:47 charon: 15[ENC] generating INFORMATIONAL request 486 [ D ]
Sep  5 16:18:47 ikem.vx:
/vobs/fbsr_plat/ikem/ikem/src/ikem_XfrmNetlinkListener.cc:94/handleXFRM_MSG_EXPIRE
pid=760 ERR XFRM_MSG_EXPIRE hard expiry
Sep  5 16:18:47 ikem.vx:
/vobs/fbsr_plat/ikem/ikem/src/ikem_XfrmNetlinkListener.cc:94/handleXFRM_MSG_EXPIRE
pid=760 ERR XFRM_MSG_EXPIRE hard expiry
Sep  5 16:18:47 charon: 13[KNL] querying SAD entry with SPI c6739a46
failed: No such process (3)
Sep  5 16:18:47 charon: 13[KNL] querying SAD entry with SPI 109d7b5d
failed: No such process (3)
Sep  5 16:18:47 charon: 13[IKE] closing CHILD_SA tun1_sa1{1} with SPIs
c6739a46_i (12524353 bytes) 109d7b5d_o (11944303 bytes) and TS 10.2.4.115/32===
10.13.125.62/32 10.250.232.249/32 10.250.30.6/32 10.250.30.10/32
10.250.30.14/32 10.250.30.18/32 10
Sep  5 16:18:47 charon: 13[IKE] closing CHILD_SA tun1_sa1{1} with SPIs
c6739a46_i (12524353 bytes) 109d7b5d_o (11944303 bytes) and TS 10.2.4.115/32===
10.13.125.62/32 10.250.232.249/32 10.250.30.6/32 10.250.30.10/32
10.250.30.14/32 10.250.30.18/32 10
Sep  5 16:18:47 charon: 13[ENC] generating INFORMATIONAL request 487 [ D ]

For some strange reason , charon is trying to query the SAD with an SPI ,
thats been already deleted . Any pointers to why this would have occurred ?

Thanks ,

-- 

Best Regards,

Rajesh Bhaskaran.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.strongswan.org/pipermail/users/attachments/20120906/dce9dae2/attachment.html>