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

chaitanya vinnakota chaitanya.sai.v at gmail.com
Fri Oct 21 12:35:24 CEST 2016 

Hi Tobias,

The mode configured in strongswan is "push"  and the IP assignment to the
VPN client happened after activating MODE_CONFIG task . I'm also sorry to
confuse you with incorrect configuration.   The below is the configuration
running in the current scenario.


conn c2s_ShrewSoftSrv
        auto=add
        left=44.44.44.1
        right=44.44.44.2
        aggressive=yes
        leftauth=psk
        rightauth=psk
        leftid=44.44.44.1
        rightid=44.44.44.2
        ike=3des-sha1-modp1024!
        ikelifetime=28800s
        esp=3des-sha1!
        lifetime=3600s
        rekeymargin=180s
        dpddelay=40
        dpdtimeout=120
        dpdaction=clear
        rightsourceip=%config
        modeconfig=push
        leftsubnet=0.0.0.0/0
        rightauth2=xauth
        xauth=server
        rightdns=192.168.1.1

Below is the excerpt from the logs, where IP assignment [10.0.0.1] proposed
by the VPN client happened after activating MODE_CONFIG task.

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


After initiation of MODE_CONFIG task , all the subsequent tasks like DPD
are queued but never scheduled. ShrewSoft VPN client teared down the
connection as it did'nt receive the responses for the 6 DPD requests sent.
Below is the excerpt from the strongswan logs:-


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 vpn:<notice> - 44.44.44.2 10.0.0.1/32 ==
44.44.44.2 -- 44.44.44.1 == 0.0.0.0/0
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 Fri, Oct 21, 2016 at 12:42 PM, Tobias Brunner <tobias at strongswan.org>
wrote:

> Hi,
>
> > 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) ]
>
> Your client seems to send a Mode Config request after strongSwan already
> pushed config options.  strongSwan can't handle that, it expects either
> push or pull mode (as configured) but not both.
>
> Regards,
> Tobias
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.strongswan.org/pipermail/users/attachments/20161021/8cf78654/attachment.html>

More information about the Users mailing list