[Swan-dev] ikev1 xauth regression

Wed May 2 15:05:55 UTC 2018

On 13 April 2018 at 15:25, Andrew Cagney <andrew.cagney at gmail.com> wrote:
> I took a more careful look.  Its because the cert authentication has
> become slower for some reason:

... and I'm wondering if the cause of the slowdown was ElectricFence.
 Even though around that time the test results were terrible:

v3.22-1007-g86105a8-master 82
    ...
    https://github.com/libreswan/libreswan/commit/96015a9
    +003 "xauth-road-eastnet" #1: Authenticated using RSA
    ....
v3.22-1018-ga436114-master 430
v3.22-1021-g5aac734-master 431
    ...
    https://github.com/libreswan/libreswan/commit/10bab7d
    policy values all change
    ....
v3.22-1045-g299b165-master 537
    ...
   https://github.com/libreswan/libreswan/commit/868e518
   EFENCE=-lefence
    ....
v3.22-1080-g6e40294-master 544
   ...
   expect new and sorted policy values
   ....
v3.22-1095-g2075aa8-master 203

there still seems to be a slight bump when electric fence was enabled;
and looking at the results some of the extra failures do show the
crypto slowdown.

To test this theory, I'll set up the next test run on
testing.libreswan.org so that EFENCE is disabled.

Andrew

> ROAD sends a certificate et.al:
>
> | sending 1336 bytes for STATE_MAIN_R2 through eth1:4500 to <ip
> address>:4500 (using #1)
> |   00 00 00 00  3e 7a fd c4  cd 49 b7 be  6d dc 98 71
>
> EAST receives receives it (discarding nat prefix) and then takes its
> sweet time to process it using the _main_ thread:
>
> | *received 1476 bytes from 192.1.2.254:4500 on eth1 (port=4500)
> |   3e 7a fd c4  cd 49 b7 be  6d dc 98 71  97 00 51 76
>
> Meanwhile ROAD gets impatient and starts sending EAST fragmented re-transmits:
>
> +010 "modecfg-road-east" #1: STATE_MAIN_I3: retransmission; will wait
> 0.5 seconds for response
> +010 "modecfg-road-east" #1: STATE_MAIN_I3: retransmission; will wait
> 1 seconds for response
> +010 "modecfg-road-east" #1: STATE_MAIN_I3: retransmission; will wait
> 2 seconds for response
>
> (these all get queued up in the receive socket because EAST's tied up
> the main thread)
>
> EAST then finishes its work, sends the reply (and schedules a
> back-to-back password request packet):
>
> | sending 1336 bytes for STATE_MAIN_R2 through eth1:4500 to <ip
> address>:4500 (using #1)
> |   00 00 00 00  3e 7a fd c4  cd 49 b7 be  6d dc 98 71
> "modecfg-road-east"[1] <ip address> #1: STATE_MAIN_R3: sent MR3,
> ISAKMP SA established {auth=RSA_SIG cipher=3des_cbc_192 integ=sha
> group=MODP2048}
>
> which ROAD receives and starts processing (again, slowly and using the
> main thread):
>
> | *received 1332 bytes from 192.1.2.23:4500 on eth0 (port=4500)
>
> meanwhile EAST both works through the backlog of retransmits
> (discarding them) and sends the  XAUTH password request packet:
>
> | *received 528 bytes from 192.1.2.254:4500 on eth1 (port=4500)
> ...
> | received IKE fragment id '1', number '1'
> ...
> "modecfg-road-east"[1] <ip address> #1: XAUTH: Sending
> Username/Password request (MAIN_R3->XAUTH_R0)
> | parent state #1: STATE_MAIN_R3(established-authenticated-ike) =>
> STATE_XAUTH_R0(established-authenticated-ike)
> | sending 72 bytes for XAUTH: req through eth1:4500 to <ip
> address>:4500 (using #1)
> | "modecfg-road-east"[1] <ip address> #1: discarding duplicate packet;
> already STATE_XAUTH_R0
>
> Now, since ROAD's beeing slow, it's EAST's turn to get impatient and
> send fragmented re-transmits, which of course sit in ROAD's queue ....
>
> ROAD, then finishes its AUTH, and starts processing the packet
> backlog.  At the very front is the password request from EAST:
>
> | *received 68 bytes from 192.1.2.23:4500 on eth0 (port=4500)
> |   3e 7a fd c4  cd 49 b7 be  6d dc 98 71  97 00 51 76
>
> to which it responds:
>
> "modecfg-road-east" #1: XAUTH: Answering XAUTH challenge with user='use3'
> | sending 88 bytes for STATE_XAUTH_I0 through eth0:4500 to
> 192.1.2.23:4500 (using #1)
> |   00 00 00 00  3e 7a fd c4  cd 49 b7 be  6d dc 98 71
>
> however, behind that are all the re-transmits (both for AUTH and for
> XAUTH).  For AUTH packets, ROAD:
>
> "modecfg-road-east" #1: message ignored because it contains an
> unexpected payload type (ISAKMP_NEXT_ID)
> "modecfg-road-east" #1: sending encrypted notification
> INVALID_PAYLOAD_TYPE to 192.1.2.23:4500
> | *received 68 bytes from 192.1.2.23:4500 on eth0 (port=4500)
>
> (which EAST ignores), and for XAUTH, it sends a duplicate credential:
>
> "modecfg-road-east" #1: XAUTH: Answering XAUTH challenge with user='use3'
> | sending 88 bytes for STATE_XAUTH_I0 through eth0:4500 to
> 192.1.2.23:4500 (using #1)
> |   00 00 00 00  3e 7a fd c4  cd 49 b7 be  6d dc 98 71
>
> for the re-transmitted password requests.  Fortunately EAST discards
> this and, eventually, the two ends catch up and bring up the
> connection.
>
> For the tests, hobbling re-transmits should make it more deterministic.
>
> Andrew
>
>
> On 18 March 2018 at 19:31, Paul Wouters <paul at nohats.ca> wrote:
>>> Date: Sun, 18 Mar 2018 15:58:50
>>> The regression tests are consistently throwing up this failure:
>>>
>>>
>>> http://testing.libreswan.org/results/v3.22-1133-gcc9c2b1-master/xauth-pluto-16/OUTPUT/road.console.diff
>>>
>>> Looking through history, it started after these changes:
>>>
>>> 2018-03-02 02:20:96015a9pluto: Support for fallback to AUTH_NULL via
>>> private use notify
>>> 2018-03-02 02:17:398dd7dpluto: log any ID_NULL identity given then
>>> forget about it forever
>>> 2018-03-02 02:13:5d22830libipsecconf: Add support for authby=foo,bar
>>> 2018-03-02 01:44:3845655testing: test bogus payloads in SA_INIT exchange
>>> 2018-03-02 01:30:064c0b1retransmits: add --impair delete-on-retransmit
>>> 2018-03-01 20:48:cc6f7f0packaging: don't use @ @ symbols for ipsec version
>>> 2018-03-01 19:22:c306de3ikev2: move 'set current state' to before the
>>> packet decode
>>>
>>> I suspect there's timing involved though, locally I'm not seeing this.
>>
>>
>> I guess I'll git bisect this to find the specific commit. The first two
>> are only changing IKEv2, and this shows up as an IKEv1 problem, so I'm
>> a little confused how this happened.
>>
>> Paul