[strongSwan] StrongSwan not responding to DPD messages when modeconfig=push.
chaitanya vinnakota
chaitanya.sai.v at gmail.com
Sat Oct 29 10:08:53 CEST 2016
Hi All Stalwarts out there ,
Based on the strongswan logs , it is evident that the Strongswan server is
waiting for the acknowledgement for the below request from the ShrewSoft
VPN Client.
Sep 24 12:58:15 router6654A1 charon:<info> 15[ENC] generating TRANSACTION
request 1589939411 [ HASH CPS(ADDR DNS) ]
The ShrewSoft VPN Client is not responding to the messages and therefore
Strongswan is indefinitely waiting for the response , subsequently queuing
all the new requests [DPD Requests] and the client finally tearing down the
connection as DPD response is not received.
We've the following questions .
1. Why does strongswan wait for the response in spite of assigning the
IP requested by client ?
2. Sometimes , shrew soft client is reporting "Invalid message from the
gateway" for this transaction request HASH CPS(ADDR DNS) and closing the
connection ?
3. Is this an interoperability issue ? Is Shrew soft client not
interoperable with Mode-Config standard ?
Awaiting the response badly.
Thanks
Chaitanya
On Fri, Oct 21, 2016 at 4:05 PM, chaitanya vinnakota <
chaitanya.sai.v at gmail.com> wrote:
> 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/20161029/0fc2d99e/attachment-0001.html>
More information about the Users
mailing list