search

xelerance / Openswan

Openswan
Other
852 stars 214 forks source link

IPsec Tunnel Deterministic Delay #156

Open japita-se opened 8 years ago

japita-se commented 8 years ago

0 down vote favorite I setup a site-to-site IPSec tunnel using OpensWan. I noticed that there is always a delay of 15 sec betwenn the phase 1 and phase 2 as shown in this tcpdump. Does anybody know why?

17:50:41.638828 IP remotepeer.40237 > miyazaki.47087: Flags [S.], seq 539598201, ack 3547092391, win 5792, options [mss 1380,sackOK,TS val 1866473592 ecr 1322888897,nop,wscale 3], length 0 17:50:41.695067 IP remotepeer.40237 > miyazaki.47087: Flags [.], ack 593, win 872, options [nop,nop,TS val 1866473647 ecr 1322888954], length 0 17:50:41.897514 IP remotepeer.40237 > miyazaki.47087: Flags [P.], seq 1:161, ack 593, win 872, options [nop,nop,TS val 1866473850 ecr 1322888954], length 160 17:50:41.952144 IP remotepeer.40237 > miyazaki.47087: Flags [P.], seq 161:426, ack 593, win 872, options [nop,nop,TS val 1866473905 ecr 1322889212], length 265 17:50:56.897125 IP remotepeer.40237 > miyazaki.47087: Flags [F.], seq 426, ack 593, win 872, options [nop,nop,TS val 1866488851 ecr 1322889267], length 0 17:50:56.952014 IP remotepeer.40237 > miyazaki.47087: Flags [.], ack 594, win 872, options [nop,nop,TS val 1866488906 ecr 1322904212], length 0

letoams commented 8 years ago

On Wed, 25 Nov 2015, japita-se wrote:

Subject: [Openswan] IPsec Tunnel Deterministic Delay (#156)

I setup a site-to-site IPSec tunnel using OpensWan. I noticed that there is always a delay of 15 sec betwenn the phase 1 and phase 2 as shown in this tcpdump. Does anybody know why?

17:50:41.638828 IP remotepeer.40237 > miyazaki.47087: Flags [S.], seq 539598201, ack 3547092391, win 5792, options [mss 1380,sackOK,TS val 1866473592 ecr 1322888897,nop,wscale 3], length 0 17:50:41.695067 IP remotepeer.40237 > miyazaki.47087: Flags [.], ack 593, win 872, options [nop,nop,TS val 1866473647 ecr 1322888954], length 0 17:50:41.897514 IP remotepeer.40237 > miyazaki.47087: Flags [P.], seq 1:161, ack 593, win 872, options [nop,nop,TS val 1866473850 ecr 1322888954], length 160 17:50:41.952144 IP remotepeer.40237 > miyazaki.47087: Flags [P.], seq 161:426, ack 593, win 872, options [nop,nop,TS val 1866473905 ecr 1322889212], length 265

Looks like there was fragmentation at the UDP layer there? Perhaps the fragment got lost?

17:50:56.897125 IP remotepeer.40237 > miyazaki.47087: Flags [F.], seq 426, ack 593, win 872, options [nop,nop,TS val 1866488851 ecr 1322889267], length 0 17:50:56.952014 IP remotepeer.40237 > miyazaki.47087: Flags [.], ack 594, win 872, options [nop,nop,TS val 1866488906 ecr 1322904212], length 0

libreswan supports IKEv1 and IKEv2 fragmentation so UDP packets won't need to fragment. Perhaps that might help you?

Paul

japita-se commented 8 years ago

I admit my ignorance of libreswan details. I do not know if it is a fragmentation problem. In other forums where people paste their packet dumps the I saw the same issue (exactly 15 secs of delay between the conclusion of phase 2 even if the packets arrive immediately). How can I debug?

letoams commented 8 years ago

plutodebug=all

Sent from my iPhone

On Nov 26, 2015, at 04:22, japita-se notifications@github.com wrote:

I admit my ignorance of libreswan details. I do not know if it is a fragmentation problem. In other forums where people paste their packet dumps the I saw the same issue (exactly 15 secs of delay between the conclusion of phase 2 even if the packets arrive immediately). How can I debug?

— Reply to this email directly or view it on GitHub.

japita-se commented 8 years ago

It was already set. I see a lot of "unpadded size is: 56 An excerpt of /var/log/plugo.log:

_received 84 bytes from remore-ip:500 on eth1 (port=500) | 0b 7a b2 6c 39 3a 76 54 e0 8e 75 0f 6e 41 39 93 | 08 10 05 01 73 0f 67 6b 00 00 00 54 bd ce 34 1f | 81 f2 a9 12 f3 9a 15 d6 8f f7 b7 10 19 65 18 f9 | e8 db 2d 1d a2 05 12 42 f1 b1 35 1b c5 0e c5 ab | e6 37 2f af 64 6a fb 00 be 58 63 bf 9d 08 36 4f | 4a e3 df ec | *_parse ISAKMP Message: | initiator cookie: | 0b 7a b2 6c 39 3a 76 54 | responder cookie: | e0 8e 75 0f 6e 41 39 93 | next payload type: ISAKMP_NEXT_HASH | ISAKMP version: ISAKMP Version 1.0 (rfc2407) | exchange type: ISAKMP_XCHG_INFO | flags: ISAKMP_FLAG_ENCRYPTION | message ID: 73 0f 67 6b | length: 84 | processing version=1.0 packet with exchange type=ISAKMP_XCHG_INFO (5) | ICOOKIE: 0b 7a b2 6c 39 3a 76 54 | RCOOKIE: e0 8e 75 0f 6e 41 39 93 | state hash entry 13 | peer and cookies match on #23114, provided msgid 00000000 vs a8e57c89/00000000 | peer and cookies match on #23113, provided msgid 00000000 vs 581c1d95/00000000 | peer and cookies match on #23112, provided msgid 00000000 vs 00000000/00000000 | p15 state object #23112 found, in STATE_MAIN_R3 | processing connection remotepeer/0x1 | last Phase 1 IV: a2 7b d6 67 67 57 bc 9b | current Phase 1 IV: a2 7b d6 67 67 57 bc 9b | computed Phase 2 IV: | 67 03 0c 9b f6 9f 3d 7e 4c 24 96 21 bc 61 d1 41 | 7c 60 c2 bd | received encrypted packet from remoteip:500 | decrypting 56 bytes using algorithm OAKLEY_3DES_CBC | NSS: do_3des init start | NSS: do_3des init end | decrypted:

letoams commented 8 years ago

On Thu, 26 Nov 2015, japita-se wrote:

It was already set. I see a lot of "unpadded size is: 56 An excerpt of /var/log/plugo.log:

you need to know the log of what happens in/around the 15 seconds.

libreswan has an option logtime=yes that will also log timestamps.

Paul