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

chaitanya vinnakota chaitanya.sai.v at gmail.com
Fri Oct 21 05:17:31 CEST 2016 

Hi All,

Help required to identify the root cause for "hung state " of the task
MODE_CONFIG.  As it is evident from the logs , the task MODE_CONFIG is
activated but not completed. is However, even when MODE_CONFIG  is not
completed, the virtual IP has been successfully assigned to the ShrewSoft
VPN client. All the tasks which are received/activated after MODE_CONFIG
task are getting queued but not getting scheduled.

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


Below is the output of "ipsec statusall" command which shows that
"INFORMATIONAL" tasks are queued.

  Status of IKE charon daemon (weakSwan 5.3.0, Linux 3.2.54, armv7l):
  uptime: 22 hours, since Sep 23 14:20:26 2012
  malloc: sbrk 229376, mmap 0, used 149792, free 79584
  worker threads: 11 of 16 idle, 5/0/0/0 working, job queue: 0/0/0/0,
scheduled: 146
  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
Virtual IP pools (size/online/offline):
  10.0.0.10-10.0.0.100: 91/0/1
  111.0.0.10-111.0.0.100: 91/0/1
Listening IP addresses:
  1.1.1.1
  44.44.44.1
  192.168.1.1
  fec0::1
Connections:
c2s_ShrewSoftSrv:  44.44.44.1...44.44.44.2  IKEv1 Aggressive, dpddelay=40s
c2s_ShrewSoftSrv:   local:  [44.44.44.1] uses pre-shared key authentication
c2s_ShrewSoftSrv:   remote: [44.44.44.2] uses pre-shared key authentication
c2s_ShrewSoftSrv:   remote: uses XAuth authentication: any
c2s_ShrewSoftSrv:   child:  0.0.0.0/0 === dynamic TUNNEL, dpdaction=clear
Security Associations (1 up, 0 connecting):
c2s_ShrewSoftSrv[806]: ESTABLISHED 7 seconds ago,
44.44.44.1[44.44.44.1]...44.44.44.2[44.44.44.2]
c2s_ShrewSoftSrv[806]: Remote XAuth identity: cisco
c2s_ShrewSoftSrv[806]: IKEv1 SPIs: f21d79575e4df3d3_i aee24673abcc008f_r*,
pre-shared key reauthentication in 7 hours
c2s_ShrewSoftSrv[806]: IKE proposal:
3DES_CBC/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
*c2s_ShrewSoftSrv[806]: Tasks queued: INFORMATIONAL*
c2s_ShrewSoftSrv{42}:  INSTALLED, TUNNEL, reqid 37, ESP SPIs: cc9487a6_i
ac159eb3_o
c2s_ShrewSoftSrv{42}:  3DES_CBC/HMAC_SHA1_96, 0 bytes_i, 0 bytes_o,
rekeying in 4 minutes
c2s_ShrewSoftSrv{42}:   0.0.0.0/0 === 10.0.0.1/32

Help is highly appreciated as I exhausted all my options in identifying the
root cause of the problem.

Thanks
Chaitanya

On Wed, Oct 19, 2016 at 10:16 PM, chaitanya vinnakota <
chaitanya.sai.v at gmail.com> wrote:

> 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
> >
> >
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.strongswan.org/pipermail/users/attachments/20161021/1084a6be/attachment-0001.html>

More information about the Users mailing list