[strongSwan] StrongSwan not responding to DPD messages when modeconfig=push.

chaitanya vinnakota chaitanya.sai.v at gmail.com
Wed Oct 19 18:46:07 CEST 2016 

Hi Noel,

Thanks for the reply. I posted the wrong strongswan configuration ,
but the DPD issue and reported logs are authentic. The actual
configuration contains "modeconfig=push".

>>The logs indicate that charon delayed the execution of the DPD task because
>>a transaction (mode config) is in progress.

Strongswan successfully assigned the client proposed IP to the VPN
client.  Can modeconfig transaction be in progress even after
successful completion of Quick mode   ?

Is there a way to see which transaction is in progress ?

Below is the complete log:

Sep 24 12:58:15 router6654A1 charon:<info> 07[NET] received packet:
from 44.44.44.2[500] to 44.44.44.1[500] (512 bytes)
Sep 24 12:58:15 router6654A1 charon:<info> 07[ENC] parsed AGGRESSIVE
request 0 [ SA KE No ID V V V V V V V V V V V V V ]
Sep 24 12:58:15 router6654A1 charon:<info> 07[CFG] looking for an ike
config for 44.44.44.1...44.44.44.2
Sep 24 12:58:15 router6654A1 charon:<info> 07[CFG]   candidate:
44.44.44.1...44.44.44.2, prio 3100
Sep 24 12:58:15 router6654A1 charon:<info> 07[CFG] configured
proposals: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
Sep 24 12:58:15 router6654A1 charon:<info> 07[CFG]   proposal matches
Sep 24 12:58:15 router6654A1 charon:<info> 07[CFG] found matching ike
config: 44.44.44.1...44.44.44.2 with prio 3100
Sep 24 12:58:15 router6654A1 charon:<info> 07[IKE] received XAuth vendor ID
Sep 24 12:58:15 router6654A1 charon:<info> 07[IKE] received
draft-ietf-ipsec-nat-t-ike-00 vendor ID
Sep 24 12:58:15 router6654A1 charon:<info> 07[ENC] received unknown
vendor ID: 16:f6:ca:16:e4:a4:06:6d:83:82:1a:0f:0a:ea:a8:62
Sep 24 12:58:15 router6654A1 charon:<info> 07[IKE] received
draft-ietf-ipsec-nat-t-ike-02\n vendor ID
Sep 24 12:58:15 router6654A1 charon:<info> 07[IKE] received
draft-ietf-ipsec-nat-t-ike-03 vendor ID
Sep 24 12:58:15 router6654A1 charon:<info> 07[IKE] received NAT-T (RFC
3947) vendor ID
Sep 24 12:58:15 router6654A1 charon:<info> 07[IKE] received
FRAGMENTATION vendor ID
Sep 24 12:58:15 router6654A1 charon:<info> 07[IKE] received DPD vendor ID
Sep 24 12:58:15 router6654A1 charon:<info> 07[ENC] received unknown
vendor ID: 3b:90:31:dc:e4:fc:f8:8b:48:9a:92:39:63:dd:0c:49
Sep 24 12:58:15 router6654A1 charon:<info> 07[ENC] received unknown
vendor ID: f1:4b:94:b7:bf:f1:fe:f0:27:73:b8:c4:9f:ed:ed:26
Sep 24 12:58:15 router6654A1 charon:<info> 07[ENC] received unknown
vendor ID: 16:6f:93:2d:55:eb:64:d8:e4:df:4f:d3:7e:23:13:f0:d0:fd:84:51
Sep 24 12:58:15 router6654A1 charon:<info> 07[ENC] received unknown
vendor ID: 84:04:ad:f9:cd:a0:57:60:b2:ca:29:2e:4b:ff:53:7b
Sep 24 12:58:15 router6654A1 charon:<info> 07[IKE] received Cisco
Unity vendor ID
Sep 24 12:58:15 router6654A1 charon:<info> 07[IKE] 44.44.44.2 is
initiating a Aggressive Mode IKE_SA
Sep 24 12:58:15 router6654A1 charon:<info> Last message '07[IKE]
44.44.44.2 i' repeated 1 times, supressed by syslog-ng on router6654A1
Sep 24 12:58:15 router6654A1 charon:<info> 07[IKE] IKE_SA
(unnamed)[806] state change: CREATED => CONNECTING
Sep 24 12:58:15 router6654A1 charon:<info> 07[CFG]   proposal matches
Sep 24 12:58:15 router6654A1 charon:<info> 07[CFG] received proposals:
IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
Sep 24 12:58:15 router6654A1 charon:<info> 07[CFG] configured
proposals: IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
Sep 24 12:58:15 router6654A1 charon:<info> 07[CFG] selected proposal:
IKE:3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
Sep 24 12:58:15 router6654A1 charon:<info> 07[CFG] looking for
XAuthInitPSK peer configs matching 44.44.44.1...44.44.44.2[44.44.44.2]
Sep 24 12:58:15 router6654A1 charon:<info> 07[CFG]   candidate
"c2s_ShrewSoftSrv", match: 1/20/3100 (me/other/ike)
Sep 24 12:58:15 router6654A1 charon:<info> 07[CFG] selected peer
config "c2s_ShrewSoftSrv"
Sep 24 12:58:15 router6654A1 charon:<info> 07[IKE] sending XAuth vendor ID
Sep 24 12:58:15 router6654A1 charon:<info> 07[IKE] sending DPD vendor ID
Sep 24 12:58:15 router6654A1 charon:<info> 07[IKE] sending Cisco Unity vendor ID
Sep 24 12:58:15 router6654A1 charon:<info> 07[IKE] sending NAT-T (RFC
3947) vendor ID
Sep 24 12:58:15 router6654A1 charon:<info> 07[IKE] Searching for PSK
with :my_id,me,other_id,other: '44.44.44.1'[44.44.44.1] -
'44.44.44.2'[44.44.44.2]
Sep 24 12:58:15 router6654A1 charon:<info> 07[IKE] Got the shared
secret key 'thisispsk'.
Sep 24 12:58:15 router6654A1 charon:<info> 07[ENC] generating
AGGRESSIVE response 0 [ SA KE No ID NAT-D NAT-D HASH V V V V ]
Sep 24 12:58:15 router6654A1 charon:<info> 07[NET] sending packet:
from 44.44.44.1[500] to 44.44.44.2[500] (408 bytes)
Sep 24 12:58:15 router6654A1 charon:<info> 01[NET] received packet:
from 44.44.44.2[500] to 44.44.44.1[500] (100 bytes)
Sep 24 12:58:15 router6654A1 charon:<info> 01[ENC] parsed AGGRESSIVE
request 0 [ HASH NAT-D NAT-D ]
Sep 24 12:58:15 router6654A1 charon:<info> 01[IKE] queueing XAUTH task
Sep 24 12:58:15 router6654A1 charon:<info> 01[IKE] activating new tasks
Sep 24 12:58:15 router6654A1 charon:<info> 01[IKE]   activating XAUTH task
Sep 24 12:58:15 router6654A1 charon:<info> 01[ENC] generating
TRANSACTION request 2769998340 [ HASH CPRQ(X_USER X_PWD) ]
Sep 24 12:58:15 router6654A1 charon:<info> 01[NET] sending packet:
from 44.44.44.1[500] to 44.44.44.2[500] (76 bytes)
Sep 24 12:58:15 router6654A1 charon:<info> 08[NET] received packet:
from 44.44.44.2[500] to 44.44.44.1[500] (84 bytes)
Sep 24 12:58:15 router6654A1 charon:<info> 08[ENC] parsed
INFORMATIONAL_V1 request 1493163800 [ HASH N(INITIAL_CONTACT) ]
Sep 24 12:58:15 router6654A1 charon:<info> 06[NET] received packet:
from 44.44.44.2[500] to 44.44.44.1[500] (84 bytes)
Sep 24 12:58:15 router6654A1 charon:<info> 06[ENC] parsed TRANSACTION
response 2769998340 [ HASH CPRP(X_TYPE X_USER X_PWD) ]
Sep 24 12:58:15 router6654A1 charon:<info> 06[IKE] PAM authentication
has received the connection name 'c2s_ShrewSoftSrv'
Sep 24 12:58:15 router6654A1 charon:<error> PAM _pam_init_handlers: no
default config /etc/pam.d/other
Sep 24 12:58:15 router6654A1 charon:<error> pam_radius_auth: No RADIUS
server found in configuration file /etc/raddb/server
Sep 24 12:58:15 router6654A1 charon:<alert> pam_ldap: missing "host"
in file "/etc/ldap.conf"
Sep 24 12:58:15 router6654A1 charon:<error> pam_krb5(s2s-vpn:auth):
(user cisco) parse_name failed: Configuration file does not specify
default realm
Sep 24 12:58:15 router6654A1 charon:<notice> pam_krb5(s2s-vpn:auth):
authentication failure; logname=cisco uid=0 euid=0 tty= ruser= rhost=
Sep 24 12:58:15 router6654A1 charon:<info> Localdb:user:cisco
authentication sucess
Sep 24 12:58:15 router6654A1 charon:<info> Localdb authorization Sucess
Sep 24 12:58:15 router6654A1 charon:<info> 06[IKE] PAM authentication
of 'cisco' successful
Sep 24 12:58:15 router6654A1 charon:<info> 06[IKE] XAuth
authentication of 'cisco' successful
Sep 24 12:58:15 router6654A1 charon:<info> 06[IKE] reinitiating
already active tasks
Sep 24 12:58:15 router6654A1 charon:<info> 06[IKE]   XAUTH task
Sep 24 12:58:15 router6654A1 charon:<info> 06[ENC] generating
TRANSACTION request 1517300843 [ HASH CPS(X_STATUS) ]
Sep 24 12:58:15 router6654A1 charon:<info> 06[NET] sending packet:
from 44.44.44.1[500] to 44.44.44.2[500] (68 bytes)
Sep 24 12:58:15 router6654A1 charon:<info> 15[NET] received packet:
from 44.44.44.2[500] to 44.44.44.1[500] (60 bytes)
Sep 24 12:58:15 router6654A1 charon:<info> 15[ENC] parsed TRANSACTION
response 1517300843 [ HASH CP ]
Sep 24 12:58:15 router6654A1 charon:<info> 15[IKE] IKE_SA
c2s_ShrewSoftSrv[806] established between
44.44.44.1[44.44.44.1]...44.44.44.2[44.44.44.2]
Sep 24 12:58:15 router6654A1 charon:<info> Last message '15[IKE]
IKE_SA c2s_S' repeated 1 times, supressed by syslog-ng on router6654A1
Sep 24 12:58:15 router6654A1 charon:<info> 15[IKE] IKE_SA
c2s_ShrewSoftSrv[806] state change: CONNECTING => ESTABLISHED
Sep 24 12:58:15 router6654A1 charon:<info> 15[IKE] scheduling
reauthentication in 28780s
Sep 24 12:58:15 router6654A1 charon:<info> 15[IKE] maximum IKE_SA
lifetime 28795s
Sep 24 12:58:15 router6654A1 charon:<info> 15[IKE] activating new tasks
Sep 24 12:58:15 router6654A1 charon:<info> 15[IKE] nothing to initiate
Sep 24 12:58:15 router6654A1 charon:<info> 16[NET] received packet:
from 44.44.44.2[500] to 44.44.44.1[500] (148 bytes)
Sep 24 12:58:15 router6654A1 charon:<info> 16[ENC] parsed TRANSACTION
request 3221496499 [ HASH CPRQ(U_SPLITINC U_LOCALLAN U_BANNER
U_SAVEPWD U_NATTPORT VER U_FWTYPE) ]
Sep 24 12:58:15 router6654A1 charon:<info> 16[IKE] processing
UNITY_SPLIT_INCLUDE attribute
Sep 24 12:58:15 router6654A1 charon:<info> 16[IKE] processing
UNITY_LOCAL_LAN attribute
Sep 24 12:58:15 router6654A1 charon:<info> 16[IKE] processing
UNITY_BANNER attribute
Sep 24 12:58:15 router6654A1 charon:<info> 16[IKE] processing
UNITY_SAVE_PASSWD attribute
Sep 24 12:58:15 router6654A1 charon:<info> 16[IKE] processing
UNITY_NATT_PORT attribute
Sep 24 12:58:15 router6654A1 charon:<info> 16[IKE] processing
APPLICATION_VERSION attribute
Sep 24 12:58:15 router6654A1 charon:<info> 16[IKE] processing
UNITY_FW_TYPE attribute
Sep 24 12:58:15 router6654A1 charon:<info> 16[ENC] generating
TRANSACTION response 3221496499 [ HASH CPRP(DNS) ]
Sep 24 12:58:15 router6654A1 charon:<info> 16[NET] sending packet:
from 44.44.44.1[500] to 44.44.44.2[500] (76 bytes)
Sep 24 12:58:15 router6654A1 charon:<info> 15[IKE] queueing MODE_CONFIG task
Sep 24 12:58:15 router6654A1 charon:<info> 15[IKE] activating new tasks
Sep 24 12:58:15 router6654A1 charon:<info> 15[IKE]   activating MODE_CONFIG task
Sep 24 12:58:15 router6654A1 charon:<info> 15[IKE] assigning virtual
IP %any to peer 'cisco'
Sep 24 12:58:15 router6654A1 charon:<info> 15[CFG] proposing traffic
selectors for us:
Sep 24 12:58:15 router6654A1 charon:<info> 15[CFG]  0.0.0.0/0
Sep 24 12:58:15 router6654A1 charon:<info> 15[ENC] generating
TRANSACTION request 1589939411 [ HASH CPS(ADDR DNS) ]
Sep 24 12:58:15 router6654A1 charon:<info> 15[NET] sending packet:
from 44.44.44.1[500] to 44.44.44.2[500] (76 bytes)
Sep 24 12:58:15 router6654A1 charon:<info> 15[IKE] delaying task
initiation, TRANSACTION exchange in progress

Sep 24 12:58:17 router6654A1 charon:<info> 10[NET] received packet:
from 44.44.44.2[500] to 44.44.44.1[500] (156 bytes)
Sep 24 12:58:17 router6654A1 charon:<info> 10[ENC] parsed QUICK_MODE
request 1840906332 [ HASH SA No ID ID ]
Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] looking for a child
config for 0.0.0.0/0 === 10.0.0.1/32
Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] proposing traffic
selectors for us:
Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG]  0.0.0.0/0
Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] proposing traffic
selectors for other:
Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG]  0.0.0.0/0
Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG]   candidate
"c2s_ShrewSoftSrv" with prio 5+1
Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] found matching
child config "c2s_ShrewSoftSrv" with prio 6
Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] selecting traffic
selectors for other:
Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG]  config: 0.0.0.0/0,
received: 10.0.0.1/32 => match: 10.0.0.1/32
Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] selecting traffic
selectors for us:
Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG]  config: 0.0.0.0/0,
received: 0.0.0.0/0 => match: 0.0.0.0/0
Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG]   proposal matches
Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] received proposals:
ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ
Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] configured
proposals: ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ
Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] selected proposal:
ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ
Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] changing proposed
traffic selectors for us:
Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG]  0.0.0.0/0
Sep 24 12:58:17 router6654A1 charon:<info> 10[KNL] got SPI cc9487a6
Sep 24 12:58:17 router6654A1 charon:<info> 10[ENC] generating
QUICK_MODE response 1840906332 [ HASH SA No ID ID ]
Sep 24 12:58:17 router6654A1 charon:<info> 10[NET] sending packet:
from 44.44.44.1[500] to 44.44.44.2[500] (172 bytes)
Sep 24 12:58:17 router6654A1 charon:<info> 14[NET] received packet:
from 44.44.44.2[500] to 44.44.44.1[500] (156 bytes)
Sep 24 12:58:17 router6654A1 charon:<info> 14[ENC] parsed QUICK_MODE
request 3245992495 [ HASH SA No ID ID ]
Sep 24 12:58:17 router6654A1 charon:<info> 14[CFG] proposing traffic
selectors for us:
Sep 24 12:58:17 router6654A1 charon:<info> 14[CFG]  0.0.0.0/0
Sep 24 12:58:17 router6654A1 charon:<info> 14[CHD]   using 3DES_CBC
for encryption
Sep 24 12:58:17 router6654A1 charon:<info> 14[CHD]   using
HMAC_SHA1_96 for integrity
Sep 24 12:58:17 router6654A1 charon:<info> 14[CHD] adding inbound ESP SA
Sep 24 12:58:17 router6654A1 charon:<info> 14[CHD]   SPI 0xcc9487a6,
src 44.44.44.2 dst 44.44.44.1
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] deleting SAD entry
with SPI cc9487a6
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] deleted SAD entry
with SPI cc9487a6
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] adding SAD entry
with SPI cc9487a6 and reqid {37}
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL]   using encryption
algorithm 3DES_CBC with key size 192
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL]   using integrity
algorithm HMAC_SHA1_96 with key size 160
Sep 24 12:58:17 router6654A1 charon:<info> 14[CHD] adding outbound ESP SA
Sep 24 12:58:17 router6654A1 charon:<info> 14[CHD]   SPI 0xac159eb3,
src 44.44.44.1 dst 44.44.44.2
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] adding SAD entry
with SPI ac159eb3 and reqid {37}
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL]   using encryption
algorithm 3DES_CBC with key size 192
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL]   using integrity
algorithm HMAC_SHA1_96 with key size 160
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] adding policy
0.0.0.0/0 === 10.0.0.1/32 out
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] adding policy
10.0.0.1/32 === 0.0.0.0/0 in
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] getting a local
address in traffic selector 0.0.0.0/0
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] using host %any
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] using 44.44.44.2 as
nexthop to reach 44.44.44.2/32
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] 44.44.44.1 is on
interface eth2
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] installing route:
10.0.0.1/32 via 44.44.44.2 src %any dev eth2
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] getting iface index for eth2
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] adding policy
10.0.0.1/32 === 0.0.0.0/0 fwd
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] policy 0.0.0.0/0
=== 10.0.0.1/32 out already exists, increasing refcount
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] updating policy
0.0.0.0/0 === 10.0.0.1/32 out
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] policy 10.0.0.1/32
=== 0.0.0.0/0 in already exists, increasing refcount
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] updating policy
10.0.0.1/32 === 0.0.0.0/0 in
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] getting a local
address in traffic selector 0.0.0.0/0
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] using host %any
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] using 44.44.44.2 as
nexthop to reach 44.44.44.2/32
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] 44.44.44.1 is on
interface eth2
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] policy 10.0.0.1/32
=== 0.0.0.0/0 fwd already exists, increasing refcount
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] updating policy
10.0.0.1/32 === 0.0.0.0/0 fwd
Sep 24 12:58:17 router6654A1 charon:<info> 14[IKE] CHILD_SA
c2s_ShrewSoftSrv{42} established with SPIs cc9487a6_i ac159eb3_o and
TS 0.0.0.0/0 === 10.0.0.1/32
Sep 24 12:58:17 router6654A1 charon:<info> Last message '14[IKE]
CHILD_SA c2s' repeated 1 times, supressed by syslog-ng on router6654A1
Sep 24 12:58:17 router6654A1 charon:<info> 14[KNL] 44.44.44.1 is on
interface eth2
Sep 24 12:58:17 router6654A1 charon:<info> 06[NET] received packet:
from 44.44.44.2[500] to 44.44.44.1[500] (52 bytes)
Sep 24 12:58:17 router6654A1 charon:<info> 06[ENC] parsed QUICK_MODE
request 1840906332 [ HASH ]
Sep 24 12:58:17 router6654A1 charon:<info> 06[IKE] sa payload missing
Sep 24 12:58:17 router6654A1 charon:<info> 06[IKE] queueing INFORMATIONAL task
Sep 24 12:58:17 router6654A1 charon:<info> 06[IKE] delaying task
initiation, TRANSACTION exchange in progress
root at router6654A1:~# Sep 24 12:58:22 router6654A1 charon:<info>
15[NET] received packet: from 44.44.44.2[500] to 44.44.44.1[500] (156
bytes)
Sep 24 12:58:22 router6654A1 charon:<info> 15[ENC] invalid HASH_V1
payload length, decryption failed?
Sep 24 12:58:22 router6654A1 charon:<info> 15[ENC] Invalid HASH or PSK!
Sep 24 12:58:22 router6654A1 charon:<info> 15[ENC] could not decrypt payloads
Sep 24 12:58:22 router6654A1 charon:<info> 15[IKE] message parsing failed
Sep 24 12:58:22 router6654A1 charon:<info> 15[ENC] generating
INFORMATIONAL_V1 request 2833253916 [ HASH N(PLD_MAL) ]
Sep 24 12:58:22 router6654A1 charon:<info> 15[NET] sending packet:
from 44.44.44.1[500] to 44.44.44.2[500] (68 bytes)
Sep 24 12:58:22 router6654A1 charon:<info> 15[IKE] QUICK_MODE request
with message ID 3245992495 processing failed
Status of IKE charon daemon (weakSwan 5.3.0, Linux 3.2.54, armv7l):
  loaded plugins: charon xauth-pam aes des sha1 sha2 md5 random nonce
x509 revocation constraints pubkey pkcs1 pgp dnskey pem fips-prf gmp
xcbc hmac attr kernel-pfkey kernel-netlink resolve ezvpn
socket-default stroke updown xauth-generic unity
Sep 24 12:58:23 router6654A1 charon:<info> 14[CFG] proposing traffic
selectors for us:
Sep 24 12:58:23 router6654A1 charon:<info> 14[CFG]  0.0.0.0/0
Sep 24 12:58:23 router6654A1 charon:<info> 14[CFG] proposing traffic
selectors for other:
Sep 24 12:58:23 router6654A1 charon:<info> 14[CFG]  dynamic
Sep 24 12:58:23 router6654A1 charon:<info> 14[KNL] querying SAD entry
with SPI cc9487a6
Sep 24 12:58:23 router6654A1 charon:<info> 14[KNL] querying SAD entry
with SPI ac159eb3
Sep 24 12:58:27 router6654A1 charon:<info> 06[NET] received packet:
from 44.44.44.2[500] to 44.44.44.1[500] (156 bytes)
Sep 24 12:58:27 router6654A1 charon:<info> 06[ENC] invalid HASH_V1
payload length, decryption failed?
Sep 24 12:58:27 router6654A1 charon:<info> 06[ENC] Invalid HASH or PSK!
Sep 24 12:58:27 router6654A1 charon:<info> 06[ENC] could not decrypt payloads
Sep 24 12:58:27 router6654A1 charon:<info> 06[IKE] message parsing failed
Sep 24 12:58:27 router6654A1 charon:<info> 06[ENC] generating
INFORMATIONAL_V1 request 1550766054 [ HASH N(PLD_MAL) ]
Sep 24 12:58:27 router6654A1 charon:<info> 06[NET] sending packet:
from 44.44.44.1[500] to 44.44.44.2[500] (68 bytes)
Sep 24 12:58:27 router6654A1 charon:<info> 06[IKE] QUICK_MODE request
with message ID 3245992495 processing failed
root at router6654A1:~# Sep 24 12:58:30 router6654A1 charon:<info>
13[NET] received packet: from 44.44.44.2[500] to 44.44.44.1[500] (84
bytes)
Sep 24 12:58:30 router6654A1 charon:<info> 13[ENC] parsed
INFORMATIONAL_V1 request 1159572671 [ HASH N(DPD) ]
Sep 24 12:58:30 router6654A1 charon:<info> 13[IKE] queueing ISAKMP_DPD task
Sep 24 12:58:30 router6654A1 charon:<info> 13[IKE] delaying task
initiation, TRANSACTION exchange in progress
Sep 24 12:58:32 router6654A1 charon:<info> 09[NET] received packet:
from 44.44.44.2[500] to 44.44.44.1[500] (156 bytes)
Sep 24 12:58:32 router6654A1 charon:<info> 09[ENC] invalid HASH_V1
payload length, decryption failed?
Sep 24 12:58:32 router6654A1 charon:<info> 09[ENC] Invalid HASH or PSK!
Sep 24 12:58:32 router6654A1 charon:<info> 09[ENC] could not decrypt payloads
Sep 24 12:58:32 router6654A1 charon:<info> 09[IKE] message parsing failed
Sep 24 12:58:32 router6654A1 charon:<info> 09[ENC] generating
INFORMATIONAL_V1 request 1517996381 [ HASH N(PLD_MAL) ]
Sep 24 12:58:32 router6654A1 charon:<info> 09[NET] sending packet:
from 44.44.44.1[500] to 44.44.44.2[500] (68 bytes)
Sep 24 12:58:32 router6654A1 charon:<info> 09[IKE] QUICK_MODE request
with message ID 3245992495 processing failed
Sep 24 12:58:45 router6654A1 charon:<info> 15[NET] received packet:
from 44.44.44.2[500] to 44.44.44.1[500] (84 bytes)
Sep 24 12:58:45 router6654A1 charon:<info> 15[ENC] parsed
INFORMATIONAL_V1 request 143823582 [ HASH N(DPD) ]
Sep 24 12:58:45 router6654A1 charon:<info> 15[IKE] queueing ISAKMP_DPD task
Sep 24 12:58:45 router6654A1 charon:<info> 15[IKE] delaying task
initiation, TRANSACTION exchange in progress
Sep 24 12:58:49 router6654A1 charon:<info> 14[NET] received packet:
from 44.44.44.2[500] to 44.44.44.1[500] (84 bytes)
Sep 24 12:58:49 router6654A1 charon:<info> 14[ENC] parsed
INFORMATIONAL_V1 request 547844166 [ HASH N(DPD) ]
Sep 24 12:58:49 router6654A1 charon:<info> 14[IKE] queueing ISAKMP_DPD task
Sep 24 12:58:49 router6654A1 charon:<info> 14[IKE] delaying task
initiation, TRANSACTION exchange in progress
Sep 24 12:58:52 router6654A1 charon:<info> 13[NET] received packet:
from 44.44.44.2[500] to 44.44.44.1[500] (84 bytes)
Sep 24 12:58:52 router6654A1 charon:<info> 13[ENC] parsed
INFORMATIONAL_V1 request 3233504664 [ HASH N(DPD) ]
Sep 24 12:58:52 router6654A1 charon:<info> 13[IKE] queueing ISAKMP_DPD task
Sep 24 12:58:52 router6654A1 charon:<info> 13[IKE] delaying task
initiation, TRANSACTION exchange in progress
Sep 24 12:58:54 router6654A1 charon:<info> 12[NET] received packet:
from 44.44.44.2[500] to 44.44.44.1[500] (84 bytes)
Sep 24 12:58:54 router6654A1 charon:<info> 12[ENC] parsed
INFORMATIONAL_V1 request 3103766190 [ HASH N(DPD) ]
Sep 24 12:58:54 router6654A1 charon:<info> 12[IKE] queueing ISAKMP_DPD task
Sep 24 12:58:54 router6654A1 charon:<info> 12[IKE] delaying task
initiation, TRANSACTION exchange in progress
Sep 24 12:58:55 router6654A1 charon:<info> 07[KNL] querying SAD entry
with SPI cc9487a6
Sep 24 12:58:56 router6654A1 charon:<info> 01[NET] received packet:
from 44.44.44.2[500] to 44.44.44.1[500] (68 bytes)
Sep 24 12:58:56 router6654A1 charon:<info> 01[ENC] parsed
INFORMATIONAL_V1 request 806565993 [ HASH D ]
Sep 24 12:58:56 router6654A1 charon:<info> 01[IKE] received DELETE for
ESP CHILD_SA with SPI ac159eb3
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] querying SAD entry
with SPI cc9487a6
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] querying SAD entry
with SPI ac159eb3
Sep 24 12:58:56 router6654A1 charon:<info> 01[IKE] closing CHILD_SA
c2s_ShrewSoftSrv{42} with SPIs cc9487a6_i (0 bytes) ac159eb3_o (0
bytes) and TS 0.0.0.0/0 === 10.0.0.1/32
Sep 24 12:58:56 router6654A1 charon:<info> Last message '01[IKE]
closing CHIL' repeated 1 times, supressed by syslog-ng on router6654A1
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleting policy
0.0.0.0/0 === 10.0.0.1/32 out
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] policy still used
by another CHILD_SA, not removed
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] updating policy
0.0.0.0/0 === 10.0.0.1/32 out
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleting policy
10.0.0.1/32 === 0.0.0.0/0 in
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] policy still used
by another CHILD_SA, not removed
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] updating policy
10.0.0.1/32 === 0.0.0.0/0 in
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] getting a local
address in traffic selector 0.0.0.0/0
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] using host %any
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] using 44.44.44.2 as
nexthop to reach 44.44.44.2/32
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] 44.44.44.1 is on
interface eth2
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleting policy
10.0.0.1/32 === 0.0.0.0/0 fwd
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] policy still used
by another CHILD_SA, not removed
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] updating policy
10.0.0.1/32 === 0.0.0.0/0 fwd
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleting policy
0.0.0.0/0 === 10.0.0.1/32 out
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleting policy
10.0.0.1/32 === 0.0.0.0/0 in
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] getting iface index for eth2
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleting policy
10.0.0.1/32 === 0.0.0.0/0 fwd
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleting SAD entry
with SPI cc9487a6
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleted SAD entry
with SPI cc9487a6
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleting SAD entry
with SPI ac159eb3
Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleted SAD entry
with SPI ac159eb3
Sep 24 12:58:56 router6654A1 charon:<info> 01[IKE] delaying task
initiation, TRANSACTION exchange in progress
Sep 24 12:58:56 router6654A1 charon:<info> 08[NET] received packet:
from 44.44.44.2[500] to 44.44.44.1[500] (84 bytes)
Sep 24 12:58:56 router6654A1 charon:<info> 08[ENC] parsed
INFORMATIONAL_V1 request 1876803221 [ HASH D ]
Sep 24 12:58:56 router6654A1 charon:<info> 08[IKE] received DELETE for
IKE_SA c2s_ShrewSoftSrv[806]
Sep 24 12:58:56 router6654A1 charon:<info> 08[IKE] deleting IKE_SA
c2s_ShrewSoftSrv[806] between
44.44.44.1[44.44.44.1]...44.44.44.2[44.44.44.2]
Sep 24 12:58:56 router6654A1 charon:<info> Last message '08[IKE]
deleting IKE' repeated 1 times, supressed by syslog-ng on router6654A1
Sep 24 12:58:56 router6654A1 charon:<info> 08[IKE] IKE_SA
c2s_ShrewSoftSrv[806] state change: ESTABLISHED => DELETING
Sep 24 12:58:56 router6654A1 charon:<info> 08[IKE] IKE_SA
c2s_ShrewSoftSrv[806] state change: DELETING => DELETING
Sep 24 12:58:56 router6654A1 charon:<info> 08[IKE] IKE_SA
c2s_ShrewSoftSrv[806] state change: DELETING => DESTROYING




Thanks
Chaitanya


On Wed, Oct 19, 2016 at 9:25 PM, Noel Kuntze <noel at familie-kuntze.de> wrote:
> On 19.10.2016 09:26, chaitanya vinnakota wrote:
>> Sep 24 12:58:54 router6654A1 charon:<info> 12[NET] received packet:
>> from 44.44.44.2[500] to 44.44.44.1[500] (84 bytes)
>> Sep 24 12:58:54 router6654A1 charon:<info> 12[ENC] parsed
>> INFORMATIONAL_V1 request 3103766190 [ HASH N(DPD) ]
>> Sep 24 12:58:54 router6654A1 charon:<info> 12[IKE] queueing ISAKMP_DPD task
>> Sep 24 12:58:54 router6654A1 charon:<info> 12[IKE] delaying task
>> initiation, TRANSACTION exchange in progress
>> Sep 24 12:58:55 router6654A1 charon:<info> 07[KNL] querying SAD entry
>> with SPI cc9487a6
>
> In the subject, you're writing about modeconfig=push, but you configured modeconfig=pull.
> Please make sure you configured each side correctly.
>
> The logs indicate that charon delayed the execution of the DPD task because
> a transaction (mode config) is in progress.
>
> --
>
> Mit freundlichen Grüßen/Kind Regards,
> Noel Kuntze
>
> GPG Key ID: 0x63EC6658
> Fingerprint: 23CA BB60 2146 05E7 7278 6592 3839 298F 63EC 6658
>
>

More information about the Users mailing list