Project

General

Profile

Bug #1130

strongSwan <-> racoon cert tunnel not coming UP due to INFORMATIONAL message

Added by Alexander Velkov almost 4 years ago. Updated over 3 years ago.

Status:
Closed
Priority:
Normal
Category:
libcharon
Target version:
Start date:
25.09.2015
Due date:
Estimated time:
Affected version:
5.3.3
Resolution:
Fixed

Description

Hello,

I try to setup a tunnel from a Linux box running Ubuntu 14.04 with ipsec-tools v0.8.0 (Peer2) to a box running StrongSwan v5.3.3 (Peer1).

- Peer1 (StrongSwan) is configured to run as an IPsec VPN server authenticating clients using certificates
- Peer2 (Ubuntu) is configured to run as a road-warrior client

I get different behavior in case StrongSwan is running on different architectures and have no idea why.

- When running on a big endian arm box, StrongSwan does not manage to set the up Phase1 until the end (without any error log) while racoon has Phase1 UP and is initiating Phase2.
- When running on a relatively fast little endian i686 box then the tunnel comes UP, but in some tries it showed the same error as on the other boxes.

Peer1 (StrongSwan) log:

Sep 25 01:41:51 Peer1 info ipsec_st[ 4814]: Starting strongSwan 5.3.3 IPsec [starter]...
Sep 25 01:41:51 Peer1 info kernel: Initializing XFRM netlink socket
Sep 25 01:41:51 Peer1 info charon: [ DMN] Starting IKE charon daemon (strongSwan 5.3.3, Linux 3.10.45, armv5teb)
Sep 25 01:41:51 Peer1 info charon: [ KNL] known interfaces and IP addresses:
Sep 25 01:41:51 Peer1 info charon: [ KNL] eth0
Sep 25 01:41:51 Peer1 info charon: [ KNL] 172.16.0.6
Sep 25 01:41:51 Peer1 info charon: [ LIB] loaded plugins: charon aes des sha1 sha2 md5 random nonce x509 revocation constraints pubkey pkcs1 pkcs7 pkcs8 pkcs12 pgp dnskey pem openssl fips-prf gmp xcbc hmac attr kernel-netlink resolve socket-default stroke updow
Sep 25 01:41:51 Peer1 info charon: [ JOB] spawning 32 worker threads
Sep 25 01:41:51 Peer1 info ipsec_st[ 4833]: charon (4834) started after 420 ms
Sep 25 01:43:06 Peer1 info charon: [ NET] received packet: from 172.16.0.9[500] to 172.16.0.6[500] (415 bytes)
Sep 25 01:43:06 Peer1 info charon: [ ENC] parsed AGGRESSIVE request 0 [ SA KE No ID V ]
Sep 25 01:43:06 Peer1 info charon: [ IKE] received DPD vendor ID
Sep 25 01:43:06 Peer1 info charon: [ IKE] 172.16.0.9 is initiating a Aggressive Mode IKE_SA
Sep 25 01:43:06 Peer1 info charon: [ IKE] IKE_SA (unnamed)[1] state change: CREATED => CONNECTING
Sep 25 01:43:07 Peer1 info charon: [ IKE] sending XAuth vendor ID
Sep 25 01:43:07 Peer1 info charon: [ IKE] sending DPD vendor ID
Sep 25 01:43:07 Peer1 info charon: [ IKE] sending Cisco Unity vendor ID
Sep 25 01:43:07 Peer1 info charon: [ IKE] sending cert request for "C=DE, ST=Bayern, L=Muenchen, O=Company, OU=IT,Test, CN=testca.company.com, E=stephan.wermuth@company.com" 
Sep 25 01:43:07 Peer1 info charon: [ IKE] authentication of 'C=DE, ST=Bayern, L=Muenchen, O=Company, OU=IT,Test, CN=oss30.i250, E=testmaster@company.com' (myself) successful
Sep 25 01:43:07 Peer1 info charon: [ IKE] sending end entity cert "C=DE, ST=Bayern, L=Muenchen, O=Company, OU=IT,Test, CN=oss30.i250, E=testmaster@company.com" 
Sep 25 01:43:07 Peer1 info charon: [ ENC] generating AGGRESSIVE response 0 [ SA KE No ID CERT SIG CERTREQ V V V ]
Sep 25 01:43:07 Peer1 info charon: [ NET] sending packet: from 172.16.0.6[500] to 172.16.0.9[500] (1576 bytes)
Sep 25 01:43:07 Peer1 info charon: [ NET] received packet: from 172.16.0.9[500] to 172.16.0.6[500] (84 bytes)
Sep 25 01:43:07 Peer1 info charon: [ ENC] parsed INFORMATIONAL_V1 request 3721047866 [ HASH N(INITIAL_CONTACT) ]
Sep 25 01:43:07 Peer1 info charon: [ IKE] IKE_SA ipsectest$0[1] state change: CONNECTING => DESTROYING

Peer2 (racoon on Ubuntu 14.04) log:

2015-09-25 03:42:38: INFO: @(#)ipsec-tools 0.8.0 (http://ipsec-tools.sourceforge.net)
2015-09-25 03:42:38: INFO: @(#)This product linked OpenSSL 1.0.1f 6 Jan 2014 (http://www.openssl.org/)
2015-09-25 03:42:38: INFO: Reading configuration from "/etc/racoon/racoon.conf" 
2015-09-25 03:42:38: INFO: 172.16.0.9[4500] used for NAT-T
2015-09-25 03:42:38: INFO: 172.16.0.9[4500] used as isakmp port (fd=5)
2015-09-25 03:42:38: INFO: 172.16.0.9[500] used for NAT-T
2015-09-25 03:42:38: INFO: 172.16.0.9[500] used as isakmp port (fd=6)
2015-09-25 03:43:08: INFO: IPsec-SA request for 172.16.0.6 queued due to no phase1 found.
2015-09-25 03:43:08: INFO: initiate new phase 1 negotiation: 172.16.0.9[500]<=>172.16.0.6[500]
2015-09-25 03:43:08: INFO: begin Aggressive mode.
2015-09-25 03:43:08: INFO: received Vendor ID: draft-ietf-ipsra-isakmp-xauth-06.txt
2015-09-25 03:43:08: INFO: received Vendor ID: DPD
2015-09-25 03:43:08: INFO: received Vendor ID: CISCO-UNITY
2015-09-25 03:43:08: INFO: ISAKMP-SA established 172.16.0.9[500]-172.16.0.6[500] spi:599100f9518e068e:cee950531814689f
2015-09-25 03:43:09: INFO: initiate new phase 2 negotiation: 172.16.0.9[500]<=>172.16.0.6[500]
2015-09-25 03:43:39: INFO: IPsec-SA expired: ESP/Tunnel 172.16.0.6[500]->172.16.0.9[500] spi=169700889(0xa1d6e19)
2015-09-25 03:43:39: WARNING: PF_KEY EXPIRE message received from kernel for SA being negotiated. Stopping negotiation.
2015-09-25 03:43:40: INFO: IPsec-SA expired: ESP/Tunnel 172.16.0.9[500]->172.16.0.6[500]

Peer1 configuration:

ipsec.conf:

conn ipsectest
        left=172.16.0.6
        right=0.0.0.0/0
        leftauth=pubkey
        rightauth=pubkey
        leftcert=/var/etc/strongswan/ipsec.d/certs/ipsectest-my_cert.pem
        leftsendcert=always
        rightid=%any
        aggressive=yes
        auto=ignore
        keyexchange=ikev1
        compress=no
        type=tunnel
        margintime=540s
        ike=3des-sha1-modp1024!
        ikelifetime=4200s
        esp=3des-sha1-modp1024!
        lifetime=3600s

conn ipsectest$0
        leftsubnet=10.0.0.0/16[%any/%any]
        rightsubnet=192.168.100.0/24[%any/%any]
        auto=add
        also=ipsectest

strongswan.conf:

charon {
        cisco_unity=yes
        install_routes=no
        interfaces_use=eth0
        retransmit_tries=2
        threads=32
        reauth=yes
        forceencaps=no
        mobike=no
        rekey=yes
        installpolicy=yes
        fragmentation=yes
        closeaction=none
        syslog {
                identifier=charon
                daemon {
                        default=1
                        ike=2
                        knl=2
                        cfg=0
                }
        }
}

Peer2 configuration:

racoon.conf:

listen {
        strict_address;
        isakmp 172.16.0.9 [500];
        isakmp_natt 172.16.0.9 [4500];
}

remote 172.16.0.6 {
        my_identifier asn1dn;
        certificate_type x509 "client.crt" "client.key";
        nat_traversal off;
        proposal_check obey;
        exchange_mode aggressive;
        proposal {
                lifetime time 3600 sec;
                authentication_method rsasig;
                encryption_algorithm 3des;
                hash_algorithm sha1;
                dh_group modp1024;
        }
}

sainfo address 192.168.100.0/24 any address 10.0.0.0/16 any {
        pfs_group modp1024;
        lifetime time 3600 sec;
        encryption_algorithm 3des;
        authentication_algorithm hmac_sha1;
        compression_algorithm deflate;
}

setkey.conf:

flush;                   
spdflush;                                                                                                                                                              

spdadd 192.168.100.0/24 10.0.0.0/16 any -P out ipsec
        esp/tunnel/172.16.0.9-172.16.0.6/require;
spdadd 10.0.0.0/16 192.168.100.0/24 any -P in ipsec
        esp/tunnel/172.16.0.6-172.16.0.9/require;

a.txt (267 KB) a.txt Phase 2 UP,default=1, knl=2, ike=4, enc=4 Alexander Velkov, 28.09.2015 12:54
b.txt (69.6 KB) b.txt Phase 2 UP, default=1, knl=2, ike=2, enc=2 Alexander Velkov, 28.09.2015 12:54
c.txt (1.71 KB) c.txt Phase 2 DOWN, default=1, knl=2, ike=2 Alexander Velkov, 28.09.2015 12:54

Associated revisions

Revision d7e34331
Added by Tobias Brunner over 3 years ago

Merge branch 'ikev1-cache-informational'

With these changes an INFORMATIONAL message (e.g. with an INITIAL_CONTACT
notify) that arrives while a responder is waiting for the last Aggressive
Mode request gets queued and delivered later. Previously such messages
caused the IKE_SA to fail as some tasks waiting for the last AM message
fail when trying to handle the INFORMATIONAL message. Therefore, all
other messages, such as TRANSACTION and QUICK_MODE requests, are now
dropped until AM is complete. These don't have to be cached as they get
retransmitted by the other peer.

Fixes #1130.

History

#1 Updated by Tobias Brunner almost 4 years ago

  • Category changed from charon to interoperability
  • Status changed from New to Feedback

Not sure if that has anything to do with the endianness of the hosts. It rather looks like the INFORMATIONAL sent by the client trips charon up, which probably expects the third message of the Aggressive Mode Phase 1 instead. So in the successful case you should see the INFORMATIONAL_V1 request arriving after another AGGRESSIVE request. And when it fails on the LE box you should see the same as below, i.e. the INFORMATIONAL_V1 arriving before the expected AGGRESSIVE request:

Sep 25 01:43:07 Peer1 info charon: [ ENC] generating AGGRESSIVE response 0 [ SA KE No ID CERT SIG CERTREQ V V V ]
Sep 25 01:43:07 Peer1 info charon: [ NET] sending packet: from 172.16.0.6[500] to 172.16.0.9[500] (1576 bytes)
Sep 25 01:43:07 Peer1 info charon: [ NET] received packet: from 172.16.0.9[500] to 172.16.0.6[500] (84 bytes)
Sep 25 01:43:07 Peer1 info charon: [ ENC] parsed INFORMATIONAL_V1 request 3721047866 [ HASH N(INITIAL_CONTACT) ]
Sep 25 01:43:07 Peer1 info charon: [ IKE] IKE_SA ipsectest$0[1] state change: CONNECTING => DESTROYING

I guess racoon sends the INFORMATIONAL_V1 message unencrypted. Otherwise, it would be strange that charon can actually decrypt it, as the IV for a Phase 2 exchange is based on the last block of the last Phase 1 message, which charon has not yet received. More details would be seen by increasing the log level (e.g. for enc or for ike where the IV is logged with level 4).

Not sure where it actually fails as there is no explicit error message. Would have to reproduce the issue first.

You could probably work around this by disabling the INITIAL_CONTACT notify on the client (initial_contact off;).

#2 Updated by Alexander Velkov over 3 years ago

Tobias Brunner wrote:

More details would be seen by increasing the log level (e.g. for enc or for ike where the IV is logged with lev

Hi Tobias,

thank you for your time!

I think this may be a race condition in strongSwan. I ran an equivalent test as before changing the log-levels in StrongSwan. In case the log-level is set to a higher value, then Phase 2 is being established successfully - the whole process is slown down because of the higher logging overhead.

Find attached three files with the output of strongSwan set to log in different levels in the instant racoon tries to establish the tunnel:
  • c.txt Phase 2 DOWN - default=1, knl=2, ike=2
  • b.txt Phase 2 UP - default=1, knl=2, ike=2, enc=2
  • a.txt Phase 2 UP - default=1, knl=2, ike=4, enc=4

#3 Updated by Tobias Brunner over 3 years ago

I think this may be a race condition in strongSwan.

Since charon is multi-threaded (you'd see that more clearly if you hadn't hidden the thread IDs in the log somehow) it's possible that the order in which the two messages are processed varies depending on the log levels.

Find attached three files with the output of strongSwan set to log in different levels in the instant racoon tries to establish the tunnel

Thanks. The INFORMATIONAL message is actually encrypted. That charon is able to decrypt it in both cases is because the IVs for Phase 2 messages are based on the IV of the last Phase 1 message (last encrypted block of the second to last Phase 1 message) and not on the last block of the last Phase 1 message as I previously stated.

The daemon is apparently not able to properly handle any other messages until Phase 1 is complete. I saw that some of the tasks don't check the message type when handling inbound IKEv1 messages and others (like isakmp_cert_pre) fail if the message type is not for a Phase 1 exchange, which is what causes the silent failure here.

So we could theoretically just drop the INFORMATIONAL. But since INFORMATIONALs are not acked and retransmitted in IKEv1 that won't work well (however, the message could also get lost on its way to the daemon in the first place, so that racoon sends the INITIAL_CONTACT notify in a separate exchange isn't ideal anyway). But I guess this could also happen with Mode Config in pull mode where the TRANSACTIONAL message could arrive/be processed before the last Aggressive Mode message. Same thing with Quick Mode messages. These requests get retransmitted though, so we can probably just drop them. It's all due to the ugliness of the three message Aggressive Mode exchange, so using Main Mode should also help in avoiding the issue.

To "fix" this we could perhaps cache the message and reinject it. The IKEv1 task manager already has a similar hack to handle early XAuth/Mode Config messages from the server (these get reinjected after the last Main Mode response has been processed). I tried to implement this in the 1130-cache-informational branch.

#4 Updated by Alexander Velkov over 3 years ago

Hey Tobias,

Thank you for your response.

It's all due to the ugliness of the three message Aggressive Mode exchange, so using Main Mode should also help in avoiding the issue.

That is right. I changed the configuration on both peers to use Main Mode - the tunnel comes UP successfully!

To "fix" this we could perhaps cache the message and reinject it. The IKEv1 task manager already has a similar hack to handle early XAuth/Mode Config messages from the server (these get reinjected after the last Main Mode response has been processed). I tried to implement this in the 1130-cache-informational branch.

I applied the IKEv1 patches from the 1130-cache-informational branch. The changes seem to fix the issue with the INFORMATIONAL msg - the tunnel is successfully established now also in aggressive mode. That is great!

Output on Peer1 with loglevel 'ike=3' shows new caching behavior:

Sep 30 10:19:25 Peer1 info  charon: [  NET] received packet: from 172.16.0.9[500] to 172.16.0.4[500] (415 bytes)
Sep 30 10:19:25 Peer1 info  charon: [  ENC] parsed AGGRESSIVE request 0 [ SA KE No ID V ]
Sep 30 10:19:25 Peer1 info  charon: [  IKE] received DPD vendor ID
Sep 30 10:19:25 Peer1 info  charon: [  IKE] 172.16.0.9 is initiating a Aggressive Mode IKE_SA
Sep 30 10:19:25 Peer1 info  charon: [  IKE] IKE_SA (unnamed)[1] state change: CREATED => CONNECTING
Sep 30 10:19:25 Peer1 info  charon: [  IKE] sending XAuth vendor ID
Sep 30 10:19:25 Peer1 info  charon: [  IKE] sending DPD vendor ID
Sep 30 10:19:25 Peer1 info  charon: [  IKE] sending Cisco Unity vendor ID
Sep 30 10:19:25 Peer1 info  charon: [  IKE] sending cert request for "C=DE, ST=Bayern, L=Muenchen, O=Company, OU=IT,Test, CN=testca.company.com, E=stephan.wermuth@company.com" 
Sep 30 10:19:25 Peer1 info  charon: [  IKE] HASH_R data => 474 bytes @ 0x137de38
Sep 30 10:19:25 Peer1 info  charon: [  IKE]    0: 1F 38 F9 C9 53 06 02 45 DF 3B C1 1E EF 50 6E 80  .8..S..E.;...Pn.
Sep 30 10:19:25 Peer1 info  charon: [  IKE]   16: 8A 23 DE 0D 57 A5 30 9F D6 89 9A 04 4A 00 79 2C  .#..W.0.....J.y,
Sep 30 10:19:25 Peer1 info  charon: [  IKE]   32: DB 41 16 47 5C 42 32 A5 CA 48 D5 2A BC 50 19 A5  .A.G\B2..H.*.P..
Sep 30 10:19:25 Peer1 info  charon: [  IKE]   48: 2B F4 C4 6F CB 77 B0 64 CB 92 7C 36 F6 7F 61 09  +..o.w.d..|6..a.
Sep 30 10:19:25 Peer1 info  charon: [  IKE]   64: E0 3C EB 81 B5 35 06 3C C4 45 E6 E5 B2 3D 1C 8D  .<...5.<.E...=..
Sep 30 10:19:25 Peer1 info  charon: [  IKE]   80: 78 73 3D F7 A7 BD 6F 71 0F AC 9A 7C D5 03 FE 47  xs=...oq...|...G
Sep 30 10:19:25 Peer1 info  charon: [  IKE]   96: 1A B5 DD 2A 47 12 14 09 0C 91 05 6B 9F F8 A1 D9  ...*G......k....
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  112: 3C 52 F7 A1 C3 C4 8E A9 C9 6F 95 D1 A7 6F D0 D1  <R.......o...o..
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  128: A4 EB E8 8E 7F 7C 32 D8 B7 92 A5 09 FF 9B FC D2  .....|2.........
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  144: E6 F9 09 3F 99 DF A8 40 A9 BA 64 8F 67 DD 25 93  ...?...@..d.g.%.
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  160: FC 3F C4 3A F7 44 CD 92 09 41 5E C7 85 AA 84 C2  .?.:.D...A^.....
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  176: 87 20 CE 22 21 78 A6 49 36 8C 54 30 D1 53 D7 F1  . ."!x.I6.T0.S..
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  192: FC AB EC CE 81 3D E6 32 F6 2C C8 40 A0 B2 77 61  .....=.2.,.@..wa
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  208: 03 3A EF 1D 7B 20 3E B6 88 54 89 8E BC 82 ED AC  .:..{ >..T......
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  224: A6 82 4C 77 48 27 94 30 7C 3D E8 E5 07 D4 0D C0  ..LwH'.0|=......
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  240: 3C 97 C1 2D 99 0B 22 36 6C 48 37 AE DE 61 10 2E  <..-.."6lH7..a..
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  256: 13 56 D3 F8 C4 E5 C9 C1 2C 3E E8 08 61 C1 A6 E9  .V......,>..a...
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  272: 00 00 00 01 00 00 00 01 00 00 00 28 01 01 00 01  ...........(....
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  288: 00 00 00 20 01 01 00 00 80 0B 00 01 80 0C 0E 10  ... ............
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  304: 80 01 00 01 80 03 00 03 80 02 00 02 80 04 00 02  ................
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  320: 09 00 00 00 30 81 93 31 0B 30 09 06 03 55 04 06  ....0..1.0...U..
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  336: 13 02 44 45 31 0F 30 0D 06 03 55 04 08 13 06 42  ..DE1.0...U....B
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  352: 61 79 65 72 6E 31 11 30 0F 06 03 55 04 07 13 08  ayern1.0...U....
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  368: 4D 75 65 6E 63 68 65 6E 31 11 30 0F 06 03 55 04  Muenchen1.0...U.
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  384: 0A 13 08 47 61 72 64 65 72 6F 73 31 10 30 0E 06  ...Company1.0..
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  400: 03 55 04 0B 13 07 49 54 2C 54 65 73 74 31 13 30  .U....IT,Test1.0
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  416: 11 06 03 55 04 03 13 0A 6F 73 73 33 30 2E 69 32  ...U....oss30.i2
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  432: 35 30 31 26 30 24 06 09 2A 86 48 86 F7 0D 01 09  501&0$..*.H.....
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  448: 01 16 17 74 65 73 74 6D 61 73 74 65 72 40 67 61  ...testmaster@ga
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  464: 72 64 65 72 6F 73 2E 63 6F 6D                    rderos.com
Sep 30 10:19:25 Peer1 info  charon: [  IKE] HASH_R => 20 bytes @ 0x1379e18
Sep 30 10:19:25 Peer1 info  charon: [  IKE]    0: 1B B7 1B C1 AD 03 6F 13 4C 41 D4 DA 71 BD 4D DB  ......o.LA..q.M.
Sep 30 10:19:25 Peer1 info  charon: [  IKE]   16: EC 7C 8F 54                                      .|.T
Sep 30 10:19:25 Peer1 info  charon: [  IKE] authentication of 'C=DE, ST=Bayern, L=Muenchen, O=Company, OU=IT,Test, CN=oss30.i250, E=testmaster@company.com' (myself) successful
Sep 30 10:19:25 Peer1 info  charon: [  IKE] sending end entity cert "C=DE, ST=Bayern, L=Muenchen, O=Company, OU=IT,Test, CN=oss30.i250, E=testmaster@company.com" 
Sep 30 10:19:25 Peer1 info  charon: [  ENC] generating AGGRESSIVE response 0 [ SA KE No ID CERT SIG CERTREQ V V V ]
Sep 30 10:19:25 Peer1 info  charon: [  NET] sending packet: from 172.16.0.4[500] to 172.16.0.9[500] (1576 bytes)
Sep 30 10:19:25 Peer1 info  charon: [  NET] received packet: from 172.16.0.9[500] to 172.16.0.4[500] (84 bytes)
Sep 30 10:19:25 Peer1 info  charon: [  IKE] queueing INFORMATIONAL_V1 request as tasks still active
Sep 30 10:19:25 Peer1 info  charon: [  NET] received packet: from 172.16.0.9[500] to 172.16.0.4[500] (982 bytes)
Sep 30 10:19:25 Peer1 info  charon: [  ENC] parsed AGGRESSIVE request 0 [ CERT SIG ]
Sep 30 10:19:25 Peer1 info  charon: [  IKE] received end entity cert "C=DE, ST=Bayern, L=Muenchen, O=Company, OU=IT,Test, CN=testdevice, E=stephan.wermuth@company.com" 
Sep 30 10:19:25 Peer1 info  charon: [  IKE] HASH_I data => 479 bytes @ 0x137c940
Sep 30 10:19:25 Peer1 info  charon: [  IKE]    0: A4 EB E8 8E 7F 7C 32 D8 B7 92 A5 09 FF 9B FC D2  .....|2.........
Sep 30 10:19:25 Peer1 info  charon: [  IKE]   16: E6 F9 09 3F 99 DF A8 40 A9 BA 64 8F 67 DD 25 93  ...?...@..d.g.%.
Sep 30 10:19:25 Peer1 info  charon: [  IKE]   32: FC 3F C4 3A F7 44 CD 92 09 41 5E C7 85 AA 84 C2  .?.:.D...A^.....
Sep 30 10:19:25 Peer1 info  charon: [  IKE]   48: 87 20 CE 22 21 78 A6 49 36 8C 54 30 D1 53 D7 F1  . ."!x.I6.T0.S..
Sep 30 10:19:25 Peer1 info  charon: [  IKE]   64: FC AB EC CE 81 3D E6 32 F6 2C C8 40 A0 B2 77 61  .....=.2.,.@..wa
Sep 30 10:19:25 Peer1 info  charon: [  IKE]   80: 03 3A EF 1D 7B 20 3E B6 88 54 89 8E BC 82 ED AC  .:..{ >..T......
Sep 30 10:19:25 Peer1 info  charon: [  IKE]   96: A6 82 4C 77 48 27 94 30 7C 3D E8 E5 07 D4 0D C0  ..LwH'.0|=......
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  112: 3C 97 C1 2D 99 0B 22 36 6C 48 37 AE DE 61 10 2E  <..-.."6lH7..a..
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  128: 1F 38 F9 C9 53 06 02 45 DF 3B C1 1E EF 50 6E 80  .8..S..E.;...Pn.
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  144: 8A 23 DE 0D 57 A5 30 9F D6 89 9A 04 4A 00 79 2C  .#..W.0.....J.y,
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  160: DB 41 16 47 5C 42 32 A5 CA 48 D5 2A BC 50 19 A5  .A.G\B2..H.*.P..
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  176: 2B F4 C4 6F CB 77 B0 64 CB 92 7C 36 F6 7F 61 09  +..o.w.d..|6..a.
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  192: E0 3C EB 81 B5 35 06 3C C4 45 E6 E5 B2 3D 1C 8D  .<...5.<.E...=..
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  208: 78 73 3D F7 A7 BD 6F 71 0F AC 9A 7C D5 03 FE 47  xs=...oq...|...G
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  224: 1A B5 DD 2A 47 12 14 09 0C 91 05 6B 9F F8 A1 D9  ...*G......k....
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  240: 3C 52 F7 A1 C3 C4 8E A9 C9 6F 95 D1 A7 6F D0 D1  <R.......o...o..
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  256: 2C 3E E8 08 61 C1 A6 E9 13 56 D3 F8 C4 E5 C9 C1  ,>..a....V......
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  272: 00 00 00 01 00 00 00 01 00 00 00 28 01 01 00 01  ...........(....
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  288: 00 00 00 20 01 01 00 00 80 0B 00 01 80 0C 0E 10  ... ............
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  304: 80 01 00 01 80 03 00 03 80 02 00 02 80 04 00 02  ................
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  320: 09 00 00 00 30 81 98 31 0B 30 09 06 03 55 04 06  ....0..1.0...U..
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  336: 13 02 44 45 31 0F 30 0D 06 03 55 04 08 13 06 42  ..DE1.0...U....B
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  352: 61 79 65 72 6E 31 11 30 0F 06 03 55 04 07 13 08  ayern1.0...U....
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  368: 4D 75 65 6E 63 68 65 6E 31 11 30 0F 06 03 55 04  Muenchen1.0...U.
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  384: 0A 13 08 47 61 72 64 65 72 6F 73 31 10 30 0E 06  ...Company.0..
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  400: 03 55 04 0B 13 07 49 54 2C 54 65 73 74 31 13 30  .U....IT,Test1.0
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  416: 11 06 03 55 04 03 13 0A 74 65 73 74 64 65 76 69  ...U....testdevi
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  432: 63 65 31 2B 30 29 06 09 2A 86 48 86 F7 0D 01 09  ce1+0)..*.H.....
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  448: 01 16 1C 73 74 65 70 68 61 6E 2E 77 65 72 6D 75  ...stephan.wermu
Sep 30 10:19:25 Peer1 info  charon: [  IKE]  464: 74 68 40 67 61 72 64 65 72 6F 73 2E 63 6F 6D     th@company.com
Sep 30 10:19:25 Peer1 info  charon: [  IKE] HASH_I => 20 bytes @ 0x1378dd0
Sep 30 10:19:25 Peer1 info  charon: [  IKE]    0: 27 75 DE 55 96 E3 EE 56 0D 01 34 F7 88 68 9D A0  'u.U...V..4..h..
Sep 30 10:19:25 Peer1 info  charon: [  IKE]   16: 32 F0 8C E1                                      2...
Sep 30 10:19:25 Peer1 info  charon: [  IKE] authentication of 'C=DE, ST=Bayern, L=Muenchen, O=Company, OU=IT,Test, CN=testdevice, E=stephan.wermuth@company.com' with RSA successful
Sep 30 10:19:25 Peer1 info  charon: [  IKE] IKE_SA ipsectest$0[1] established between 172.16.0.4[C=DE, ST=Bayern, L=Muenchen, O=Company, OU=IT,Test, CN=oss30.i250, E=testmaster@company.com]...172.16.0.9[C=DE, ST=Bayern, L=Muenchen, O=Company, OU=IT,Test, CN=te
Sep 30 10:19:25 Peer1 info  charon: [  IKE] IKE_SA ipsectest$0[1] state change: CONNECTING => ESTABLISHED
Sep 30 10:19:25 Peer1 info  charon: [  IKE] scheduling reauthentication in 3660s
Sep 30 10:19:25 Peer1 info  charon: [  IKE] maximum IKE_SA lifetime 4200s
Sep 30 10:19:25 Peer1 info  charon: [  ENC] parsed INFORMATIONAL_V1 request 3912547556 [ HASH N(INITIAL_CONTACT) ]
Sep 30 10:19:25 Peer1 info  charon: [  IKE] Hash => 20 bytes @ 0x137dfc0
Sep 30 10:19:25 Peer1 info  charon: [  IKE]    0: F6 AC 35 FB F3 C5 08 66 08 00 35 D6 26 50 68 5B  ..5....f..5.&Ph[
Sep 30 10:19:25 Peer1 info  charon: [  IKE]   16: 88 DE 09 48                                      ...H
Sep 30 10:19:26 Peer1 info  charon: [  NET] received packet: from 172.16.0.9[500] to 172.16.0.4[500] (292 bytes)
Sep 30 10:19:26 Peer1 info  charon: [  ENC] parsed QUICK_MODE request 2181433619 [ HASH SA No KE ID ID ]
Sep 30 10:19:26 Peer1 info  charon: [  IKE] Hash(1) => 20 bytes @ 0x137c950
Sep 30 10:19:26 Peer1 info  charon: [  IKE]    0: F9 AC 9E 06 88 3F C0 92 A6 80 05 B4 5B 5B A4 74  .....?......[[.t
Sep 30 10:19:26 Peer1 info  charon: [  IKE]   16: E9 2B E0 58                                      .+.X
Sep 30 10:19:26 Peer1 info  charon: [  KNL] got SPI c460c8c1
Sep 30 10:19:26 Peer1 info  charon: [  IKE] Hash(2) => 20 bytes @ 0x1379bd8
Sep 30 10:19:26 Peer1 info  charon: [  IKE]    0: 90 80 4C A0 8C 9D 60 B3 AF 34 F7 10 53 C9 2C 96  ..L...`..4..S.,.
Sep 30 10:19:26 Peer1 info  charon: [  IKE]   16: B7 F8 36 1D                                      ..6.
Sep 30 10:19:26 Peer1 info  charon: [  ENC] generating QUICK_MODE response 2181433619 [ HASH SA No KE ID ID ]
Sep 30 10:19:26 Peer1 info  charon: [  NET] sending packet: from 172.16.0.4[500] to 172.16.0.9[500] (308 bytes)
Sep 30 10:19:26 Peer1 info  charon: [  MGR] ignoring request with ID 2181433619, already processing
Sep 30 10:19:30 Peer1 info  charon: [  IKE] sending retransmit 1 of response message ID 2181433619, seq 2
Sep 30 10:19:30 Peer1 info  charon: [  NET] sending packet: from 172.16.0.4[500] to 172.16.0.9[500] (308 bytes)
Sep 30 10:19:30 Peer1 info  charon: [  NET] received packet: from 172.16.0.9[500] to 172.16.0.4[500] (60 bytes)
Sep 30 10:19:30 Peer1 info  charon: [  ENC] parsed QUICK_MODE request 2181433619 [ HASH ]
Sep 30 10:19:30 Peer1 info  charon: [  IKE] Hash(3) => 20 bytes @ 0x1378dd0
Sep 30 10:19:30 Peer1 info  charon: [  IKE]    0: 2E 76 CC 59 E8 0D B5 3F C9 D2 30 8B 4B 50 55 21  .v.Y...?..0.KPU!
Sep 30 10:19:30 Peer1 info  charon: [  IKE]   16: AD B0 B4 E5                                      ....
Sep 30 10:19:30 Peer1 info  charon: [  KNL] adding SAD entry with SPI c460c8c1 and reqid {1}  (mark 0/0x00000000)
Sep 30 10:19:30 Peer1 info  charon: [  KNL]   using encryption algorithm DES_CBC with key size 64
Sep 30 10:19:30 Peer1 info  charon: [  KNL]   using integrity algorithm HMAC_SHA2_512_256 with key size 512
Sep 30 10:19:30 Peer1 info  charon: [  KNL]   using replay window of 32 packets
Sep 30 10:19:30 Peer1 info  charon: [  KNL] adding SAD entry with SPI 02589ddc and reqid {1}  (mark 0/0x00000000)
Sep 30 10:19:30 Peer1 info  charon: [  KNL]   using encryption algorithm DES_CBC with key size 64
Sep 30 10:19:30 Peer1 info  charon: [  KNL]   using integrity algorithm HMAC_SHA2_512_256 with key size 512
Sep 30 10:19:30 Peer1 info  charon: [  KNL]   using replay window of 32 packets
Sep 30 10:19:30 Peer1 info  charon: [  KNL] adding policy 10.0.0.0/16 === 192.168.100.0/24 out  (mark 0/0x00000000)
Sep 30 10:19:30 Peer1 info  charon: [  KNL] adding policy 192.168.100.0/24 === 10.0.0.0/16 in  (mark 0/0x00000000)
Sep 30 10:19:30 Peer1 info  charon: [  KNL] adding policy 192.168.100.0/24 === 10.0.0.0/16 fwd  (mark 0/0x00000000)
Sep 30 10:19:30 Peer1 info  charon: [  KNL] policy 10.0.0.0/16 === 192.168.100.0/24 out  (mark 0/0x00000000) already exists, increasing refcount
Sep 30 10:19:30 Peer1 info  charon: [  KNL] updating policy 10.0.0.0/16 === 192.168.100.0/24 out  (mark 0/0x00000000)
Sep 30 10:19:30 Peer1 info  charon: [  KNL] policy 192.168.100.0/24 === 10.0.0.0/16 in  (mark 0/0x00000000) already exists, increasing refcount
Sep 30 10:19:30 Peer1 info  charon: [  KNL] updating policy 192.168.100.0/24 === 10.0.0.0/16 in  (mark 0/0x00000000)
Sep 30 10:19:30 Peer1 info  charon: [  KNL] policy 192.168.100.0/24 === 10.0.0.0/16 fwd  (mark 0/0x00000000) already exists, increasing refcount
Sep 30 10:19:30 Peer1 info  charon: [  KNL] updating policy 192.168.100.0/24 === 10.0.0.0/16 fwd  (mark 0/0x00000000)
Sep 30 10:19:30 Peer1 info  charon: [  IKE] CHILD_SA ipsectest$0{1} established with SPIs c460c8c1_i 02589ddc_o and TS 10.0.0.0/16 === 192.168.100.0/24

I think these changes make strongSwan more robust in interoperability scenarios.

Thanks a lot for the great support!

#5 Updated by Tobias Brunner over 3 years ago

  • Tracker changed from Issue to Bug
  • Subject changed from strongSwan <-> racoon cert tunnel not coming UP to strongSwan <-> racoon cert tunnel not coming UP due to INFORMATIONAL message
  • Category changed from interoperability to libcharon
  • Status changed from Feedback to Closed
  • Assignee set to Tobias Brunner
  • Target version set to 5.3.4
  • Resolution set to Fixed

Also available in: Atom PDF