<div dir="ltr"><div>Hi All Stalwarts out there , <br><br></div><div>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.<br><span style="color:rgb(204,0,0)"><span class="gmail-im"><br>Sep 24 12:58:15 router6654A1 charon:<info> 15[ENC] generating TRANSACTION request 1589939411 [ HASH CPS(ADDR DNS) ]<br></span></span></div><div><span style="color:rgb(204,0,0)"><span class="gmail-im"><br></span></span></div><div>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.<br><br></div><div>We've the following questions .<br><br> 1. Why does strongswan wait for the response in spite of assigning the IP requested by client ? <br></div><div> 2. Sometimes , shrew soft client is reporting "Invalid message from the gateway" for this transaction request <span style="color:rgb(204,0,0)"><span class="gmail-im"> HASH CPS(ADDR DNS) </span></span> and closing the connection ?<br></div><div> 3. Is this an interoperability issue ? Is Shrew soft client not interoperable with Mode-Config standard ? <br></div><div><br></div><div>Awaiting the response badly.<br></div><div><br></div><div>Thanks<br></div><div>Chaitanya<br></div><div class="gmail_extra"><br><div class="gmail_quote">On Fri, Oct 21, 2016 at 4:05 PM, chaitanya vinnakota <span dir="ltr"><<a href="mailto:chaitanya.sai.v@gmail.com" target="_blank">chaitanya.sai.v@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div><div><div>Hi Tobias,<br><br></div>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.<span class="gmail-"><br><br><br>conn c2s_ShrewSoftSrv<br> auto=add<br> left=44.44.44.1<br> right=44.44.44.2<br> aggressive=yes<br> leftauth=psk<br> rightauth=psk<br> leftid=44.44.44.1<br> rightid=44.44.44.2<br> ike=3des-sha1-modp1024!<br> ikelifetime=28800s<br> esp=3des-sha1!<br> lifetime=3600s<br> rekeymargin=180s<br> dpddelay=40<br> dpdtimeout=120<br> dpdaction=clear<br></span> rightsourceip=%config<br> modeconfig=push<br> leftsubnet=<a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a><br> rightauth2=xauth<br> xauth=server<br> rightdns=192.168.1.1<br><br></div><div>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. <br></div><div><span style="color:rgb(204,0,0)"><span class="gmail-"><br>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) ]<br></span>Sep 24 12:58:15 router6654A1 charon:<info> 16[IKE] processing UNITY_SPLIT_INCLUDE attribute<br>Sep 24 12:58:15 router6654A1 charon:<info> 16[IKE] processing UNITY_LOCAL_LAN attribute<br>Sep 24 12:58:15 router6654A1 charon:<info> 16[IKE] processing UNITY_BANNER attribute<br>Sep 24 12:58:15 router6654A1 charon:<info> 16[IKE] processing UNITY_SAVE_PASSWD attribute<br>Sep 24 12:58:15 router6654A1 charon:<info> 16[IKE] processing UNITY_NATT_PORT attribute<br>Sep 24 12:58:15 router6654A1 charon:<info> 16[IKE] processing APPLICATION_VERSION attribute<br>Sep 24 12:58:15 router6654A1 charon:<info> 16[IKE] processing UNITY_FW_TYPE attribute<span class="gmail-"><br>Sep 24 12:58:15 router6654A1 charon:<info> 16[ENC] generating TRANSACTION response 3221496499 [ HASH CPRP(DNS) ]<br></span>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)<span class="gmail-"><br>Sep 24 12:58:15 router6654A1 charon:<info> 15[IKE] queueing MODE_CONFIG task<br></span><span class="gmail-">Sep 24 12:58:15 router6654A1 charon:<info> 15[IKE] activating new tasks<br></span><span class="gmail-">Sep 24 12:58:15 router6654A1 charon:<info> 15[IKE] activating MODE_CONFIG task<br>Sep 24 12:58:15 router6654A1 charon:<info> 15[IKE] assigning virtual IP %any to peer 'cisco'<br>Sep 24 12:58:15 router6654A1 charon:<info> 15[CFG] proposing traffic selectors for us:<br></span>Sep 24 12:58:15 router6654A1 charon:<info> 15[CFG] <a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a><span class="gmail-"><br>Sep 24 12:58:15 router6654A1 charon:<info> 15[ENC] generating TRANSACTION request 1589939411 [ HASH CPS(ADDR DNS) ]<br>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)<br>Sep 24 12:58:15 router6654A1 charon:<info> 15[IKE] delaying task initiation, TRANSACTION exchange in progress<br>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)<br>Sep 24 12:58:17 router6654A1 charon:<info> 10[ENC] parsed QUICK_MODE request 1840906332 [ HASH SA No ID ID ]<br>Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] looking for a child config for <a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a> === <a href="http://10.0.0.1/32" target="_blank">10.0.0.1/32</a><br>Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] proposing traffic selectors for us:<br>Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] <a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a><br>Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] proposing traffic selectors for other:<br>Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] <a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a><br>Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] candidate "c2s_ShrewSoftSrv" with prio 5+1<br>Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] found matching child config "c2s_ShrewSoftSrv" with prio 6<br>Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] selecting traffic selectors for other:<br>Sep 24 12:58:17 router6654A1 charon:<info> 10[CFG] config: <a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a>, received: <a href="http://10.0.0.1/32" target="_blank">10.0.0.1/32</a> => match: <a href="http://10.0.0.1/32" target="_blank">10.0.0.1/32</a></span></span><br><br><br>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:-<br><span style="color:rgb(204,0,0)"><br><br></span><span style="color:rgb(153,0,0)"><span style="color:rgb(204,0,0)"><span class="gmail-">Sep 24 12:58:52 router6654A1 charon:<info> 13[IKE] queueing ISAKMP_DPD task<br>Sep 24 12:58:52 router6654A1 charon:<info> 13[IKE] delaying task initiation, TRANSACTION exchange in progress<br>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)<br>Sep 24 12:58:54 router6654A1 charon:<info> 12[ENC] parsed INFORMATIONAL_V1 request 3103766190 [ HASH N(DPD) ]<br>Sep 24 12:58:54 router6654A1 charon:<info> 12[IKE] queueing ISAKMP_DPD task<br>Sep 24 12:58:54 router6654A1 charon:<info> 12[IKE] delaying task initiation, TRANSACTION exchange in progress<br>Sep 24 12:58:55 router6654A1 charon:<info> 07[KNL] querying SAD entry with SPI cc9487a6<br>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)<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[ENC] parsed INFORMATIONAL_V1 request 806565993 [ HASH D ]<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[IKE] received DELETE for ESP CHILD_SA with SPI ac159eb3<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] querying SAD entry with SPI cc9487a6<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] querying SAD entry with SPI ac159eb3<br>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 <a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a> === <a href="http://10.0.0.1/32" target="_blank">10.0.0.1/32</a><br>Sep 24 12:58:56 router6654A1 charon:<info> Last message '01[IKE] closing CHIL' repeated 1 times, supressed by syslog-ng on router6654A1<br></span>Sep 24 12:58:56 router6654A1 vpn:<notice> - 44.44.44.2 <a href="http://10.0.0.1/32" target="_blank">10.0.0.1/32</a> == 44.44.44.2 -- 44.44.44.1 == <a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a><div><div class="gmail-h5"><br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleting policy <a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a> === <a href="http://10.0.0.1/32" target="_blank">10.0.0.1/32</a> out<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] policy still used by another CHILD_SA, not removed<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] updating policy <a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a> === <a href="http://10.0.0.1/32" target="_blank">10.0.0.1/32</a> out<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleting policy <a href="http://10.0.0.1/32" target="_blank">10.0.0.1/32</a> === <a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a> in<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] policy still used by another CHILD_SA, not removed<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] updating policy <a href="http://10.0.0.1/32" target="_blank">10.0.0.1/32</a> === <a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a> in<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] getting a local address in traffic selector <a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a><br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] using host %any<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] using 44.44.44.2 as nexthop to reach <a href="http://44.44.44.2/32" target="_blank">44.44.44.2/32</a><br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] 44.44.44.1 is on interface eth2<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleting policy <a href="http://10.0.0.1/32" target="_blank">10.0.0.1/32</a> === <a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a> fwd<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] policy still used by another CHILD_SA, not removed<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] updating policy <a href="http://10.0.0.1/32" target="_blank">10.0.0.1/32</a> === <a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a> fwd<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleting policy <a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a> === <a href="http://10.0.0.1/32" target="_blank">10.0.0.1/32</a> out<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleting policy <a href="http://10.0.0.1/32" target="_blank">10.0.0.1/32</a> === <a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a> in<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] getting iface index for eth2<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleting policy <a href="http://10.0.0.1/32" target="_blank">10.0.0.1/32</a> === <a href="http://0.0.0.0/0" target="_blank">0.0.0.0/0</a> fwd<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleting SAD entry with SPI cc9487a6<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleted SAD entry with SPI cc9487a6<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleting SAD entry with SPI ac159eb3<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[KNL] deleted SAD entry with SPI ac159eb3<br>Sep 24 12:58:56 router6654A1 charon:<info> 01[IKE] delaying task initiation, TRANSACTION exchange in progress<br>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)<br>Sep 24 12:58:56 router6654A1 charon:<info> 08[ENC] parsed INFORMATIONAL_V1 request 1876803221 [ HASH D ]<br>Sep 24 12:58:56 router6654A1 charon:<info> 08[IKE] received DELETE for IKE_SA c2s_ShrewSoftSrv[806]<br>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.<wbr>44.44.2[44.44.44.2]<br>Sep 24 12:58:56 router6654A1 charon:<info> Last message '08[IKE] deleting IKE' repeated 1 times, supressed by syslog-ng on router6654A1<br>Sep 24 12:58:56 router6654A1 charon:<info> 08[IKE] IKE_SA c2s_ShrewSoftSrv[806] state change: ESTABLISHED => DELETING<br>Sep 24 12:58:56 router6654A1 charon:<info> 08[IKE] IKE_SA c2s_ShrewSoftSrv[806] state change: DELETING => DELETING<br>Sep 24 12:58:56 router6654A1 charon:<info> 08[IKE] IKE_SA c2s_ShrewSoftSrv[806] state change: DELETING => DESTROYING</div></div></span><br><br></span></div><div><span style="color:rgb(153,0,0)"><br></span></div><div><span style="color:rgb(68,68,68)"><br><br></span></div><span style="color:rgb(68,68,68)">Thanks<span class="gmail-HOEnZb"><font color="#888888"><br></font></span></span></div><span class="gmail-HOEnZb"><font color="#888888"><span style="color:rgb(68,68,68)">Chaitanya</span><br></font></span></div><div class="gmail-HOEnZb"><div class="gmail-h5"><div class="gmail_extra"><br><div class="gmail_quote">On Fri, Oct 21, 2016 at 12:42 PM, Tobias Brunner <span dir="ltr"><<a href="mailto:tobias@strongswan.org" target="_blank">tobias@strongswan.org</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">Hi,<br>
<span><br>
> Sep 24 12:58:15 router6654A1 charon:<info> 16[ENC] parsed TRANSACTION<br>
> request 3221496499 [ HASH CPRQ(U_SPLITINC U_LOCALLAN U_BANNER<br>
> U_SAVEPWD U_NATTPORT VER U_FWTYPE) ]<br>
<br>
</span>Your client seems to send a Mode Config request after strongSwan already<br>
pushed config options. strongSwan can't handle that, it expects either<br>
push or pull mode (as configured) but not both.<br>
<br>
Regards,<br>
Tobias<br>
<br>
</blockquote></div><br></div>
</div></div></blockquote></div><br></div></div>