[Swan-dev] ikev1 xauth regression

Fri Apr 13 19:25:01 UTC 2018

I took a more careful look.  Its because the cert authentication has
become slower for some reason:

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