This discussion has been locked.
You can no longer post new replies to this discussion. If you have a question you can start a new discussion

No S2S tunnel - whack message

Hi @all!

I encountered a problem within the following setup:
One site has a static IP and ASG 220 (11.22.33.44) with actual firmware. The other side has the home version with dynamic IP (LoD-Home, 79.204.153.3) and also the actual firmware. Since version 8.203 the S2S connection isn't established automatically.

Settings on advanced tab:

local X509 cert; DPD off; NAT off; CRL auto fetching off; strict policy off; probing of preshared keys off.

I used the command center to set it up, using AES-256 (ACC) encryption.The dynamic ip is re-assigned every day at 0700am. But the connection won't establish. Also deleted and re-created the S2S connection. Then it's connecting at first try, but the next day it doesn't.

I'm quite sure this was not a problem with V 8.202. Anyone out there who can help?

Here are some log snips:


2011:12:29-07:50:42 lod pluto[30059]: loading secrets from "/etc/ipsec.secrets"
2011:12:29-07:50:42 lod pluto[30059]: loaded PSK secret for 79.204.153.3 %any
2011:12:29-07:50:42 lod pluto[30059]: loading ca certificates from '/etc/ipsec.d/cacerts'
2011:12:29-07:50:42 lod pluto[30059]: loaded ca certificate from '/etc/ipsec.d/cacerts/VPN Signing CA.pem'
2011:12:29-07:50:42 lod pluto[30059]: | authcert is already present and identical
2011:12:29-07:50:42 lod pluto[30059]: loading aa certificates from '/etc/ipsec.d/aacerts'
2011:12:29-07:50:42 lod pluto[30059]: loading ocsp certificates from '/etc/ipsec.d/ocspcerts'
2011:12:29-07:50:42 lod pluto[30059]: loading attribute certificates from '/etc/ipsec.d/acerts'
2011:12:29-07:50:42 lod pluto[30059]: Changing to directory '/etc/ipsec.d/crls'
2011:12:29-07:50:42 lod pluto[30059]: | next event EVENT_RETRANSMIT in 10 seconds for #1
2011:12:29-07:50:42 lod pluto[30059]: |
2011:12:29-07:50:42 lod pluto[30059]: | *received 68 bytes from 11.22.33.44:500 on ppp0
2011:12:29-07:50:42 lod pluto[30059]: | ICOOKIE: 61 78 1b 8c 9e 4b e3 cc
2011:12:29-07:50:42 lod pluto[30059]: | RCOOKIE: 61 b2 91 8b f6 1a 98 bd
2011:12:29-07:50:42 lod pluto[30059]: | peer: 50 9c dd d2
2011:12:29-07:50:42 lod pluto[30059]: | state hash entry 9
2011:12:29-07:50:42 lod pluto[30059]: | state object not found
2011:12:29-07:50:42 lod pluto[30059]: packet from 11.22.33.44:500: ignoring informational payload, type NO_PROPOSAL_CHOSEN
2011:12:29-07:50:42 lod pluto[30059]: | next event EVENT_RETRANSMIT in 10 seconds for #1
2011:12:29-07:50:52 lod pluto[30059]: |
...
2011:12:29-07:51:25 lod pluto[30059]: | *received whack message
...
2011:12:29-07:52:08 lod pluto[30059]: | *received 56 bytes from 11.22.33.44:500 on ppp0
2011:12:29-07:52:08 lod pluto[30059]: | ICOOKIE: 61 78 1b 8c 9e 4b e3 cc
2011:12:29-07:52:08 lod pluto[30059]: | RCOOKIE: 61 b2 91 8b f6 1a 98 bd
2011:12:29-07:52:08 lod pluto[30059]: | peer: 50 9c dd d2
2011:12:29-07:52:08 lod pluto[30059]: | state hash entry 9
2011:12:29-07:52:08 lod pluto[30059]: | state object not found
2011:12:29-07:52:08 lod pluto[30059]: packet from 11.22.33.44:500: ignoring Delete SA payload: not encrypted
2011:12:29-07:52:08 lod pluto[30059]: | next event EVENT_RETRANSMIT in 24 seconds for #1
2011:12:29-07:52:10 lod pluto[30059]: |
2011:12:29-07:52:10 lod pluto[30059]: | *received whack message
2011:12:29-07:52:10 lod pluto[30059]: | next event EVENT_RETRANSMIT in 22 seconds for #1
2011:12:29-07:52:32 lod pluto[30059]: |
2011:12:29-07:52:32 lod pluto[30059]: | *time to handle event
2011:12:29-07:52:32 lod pluto[30059]: | event after this is EVENT_REINIT_SECRET in 3467 seconds
2011:12:29-07:52:32 lod pluto[30059]: | handling event EVENT_RETRANSMIT for 11.22.33.44 "S_LoD-Home" #1
2011:12:29-07:52:32 lod pluto[30059]: | inserting event EVENT_RETRANSMIT, timeout in 40 seconds for #1
2011:12:29-07:52:32 lod pluto[30059]: | next event EVENT_RETRANSMIT in 40 seconds for #1
2011:12:29-07:52:32 lod pluto[30059]: |
2011:12:29-07:52:32 lod pluto[30059]: | *received 68 bytes from 11.22.33.44:500 on ppp0
2011:12:29-07:52:32 lod pluto[30059]: | ICOOKIE: 61 78 1b 8c 9e 4b e3 cc
2011:12:29-07:52:32 lod pluto[30059]: | RCOOKIE: a2 af c4 25 99 fe 2a 3f
2011:12:29-07:52:32 lod pluto[30059]: | peer: 50 9c dd d2
2011:12:29-07:52:32 lod pluto[30059]: | state hash entry 5
2011:12:29-07:52:32 lod pluto[30059]: | state object not found
2011:12:29-07:52:32 lod pluto[30059]: packet from 11.22.33.44:500: ignoring informational payload, type NO_PROPOSAL_CHOSEN
2011:12:29-07:52:32 lod pluto[30059]: | next event EVENT_RETRANSMIT in 40 seconds for #1
...
2011:12:29-07:52:57 lod pluto[30059]: | *received whack message
2011:12:29-07:52:57 lod pluto[30059]: "S_LoD-Home": deleting connection
2011:12:29-07:52:57 lod pluto[30059]: "S_LoD-Home" #1: deleting state (STATE_MAIN_I1)
2011:12:29-07:52:57 lod pluto[30059]: | ICOOKIE: 61 78 1b 8c 9e 4b e3 cc
2011:12:29-07:52:57 lod pluto[30059]: | RCOOKIE: 00 00 00 00 00 00 00 00
2011:12:29-07:52:57 lod pluto[30059]: | peer: 50 9c dd d2
2011:12:29-07:52:57 lod pluto[30059]: | state hash entry 5
...
2011:12:29-07:52:57 lod pluto[30059]: | *received whack message
2011:12:29-07:52:57 lod pluto[30059]: listening for IKE messages
2011:12:29-07:52:57 lod pluto[30059]: | found lo with address 127.0.0.1
2011:12:29-07:52:57 lod pluto[30059]: | found eth0 with address 192.168.1.254
2011:12:29-07:52:57 lod pluto[30059]: | found wlan0 with address 172.16.28.1
2011:12:29-07:52:57 lod pluto[30059]: | found ppp0 with address 79.204.153.3
2011:12:29-07:52:57 lod pluto[30059]: | found lo with address 0000:0000:0000:0000:0000:0000:0000:0001
2011:12:29-07:52:57 lod pluto[30059]: forgetting secrets
2011:12:29-07:52:57 lod pluto[30059]: loading secrets from "/etc/ipsec.secrets"
2011:12:29-07:52:57 lod pluto[30059]: loaded PSK secret for 79.204.153.3 %any
2011:12:29-07:52:57 lod pluto[30059]: | next event EVENT_REINIT_SECRET in 3442 seconds
2011:12:29-07:52:57 lod pluto[30059]: |
2011:12:29-07:52:57 lod pluto[30059]: | *received whack message
...
2011:12:29-08:01:07 lod pluto[30059]: |
2011:12:29-08:01:07 lod pluto[30059]: | *received whack message
2011:12:29-08:01:07 lod pluto[30059]: | from whack: got --esp=aes256-md5
2011:12:29-08:01:07 lod pluto[30059]: | esp alg added: AES_CBC_256/HMAC_MD5, cnt=1
2011:12:29-08:01:07 lod pluto[30059]: | esp proposal: AES_CBC_256/HMAC_MD5,
2011:12:29-08:01:07 lod pluto[30059]: | from whack: got --ike=aes256-md5-modp1536
2011:12:29-08:01:07 lod pluto[30059]: | ikg alg added: AES_CBC_256/HMAC_MD5/MODP_1536, cnt=1
2011:12:29-08:01:07 lod pluto[30059]: | ike proposal: AES_CBC_256/HMAC_MD5/MODP_1536,
2011:12:29-08:01:07 lod pluto[30059]: added connection description "S_LoD-Home"
2011:12:29-08:01:07 lod pluto[30059]: | 192.168.1.0/24===79.204.153.3[79.204.153.3]...11.22.33.44[11.22.33.44]===192.168.178.0/24
2011:12:29-08:01:07 lod pluto[30059]: | ike_life: 7800s; ipsec_life: 3600s; rekey_margin: 540s; rekey_fuzz: 100%; keyingtries: 0; policy: PUBKEY+ENCRYPT+TUNNEL
2011:12:29-08:01:07 lod pluto[30059]: | next event EVENT_REINIT_SECRET in 2952 seconds
...
2011:12:29-08:01:07 lod pluto[30059]: |
2011:12:29-08:01:07 lod pluto[30059]: | *received whack message
2011:12:29-08:01:07 lod pluto[30059]: | creating state object #2 at 0x945a6f8
2011:12:29-08:01:07 lod pluto[30059]: | ICOOKIE: 32 1d 4b 07 95 c9 58 40
2011:12:29-08:01:07 lod pluto[30059]: | RCOOKIE: 00 00 00 00 00 00 00 00
2011:12:29-08:01:07 lod pluto[30059]: | peer: 50 9c dd d2
2011:12:29-08:01:07 lod pluto[30059]: | state hash entry 2
2011:12:29-08:01:07 lod pluto[30059]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #2
2011:12:29-08:01:07 lod pluto[30059]: | Queuing pending Quick Mode with 11.22.33.44 "S_LoD-Home"
2011:12:29-08:01:07 lod pluto[30059]: "S_LoD-Home" #2: initiating Main Mode
2011:12:29-08:01:07 lod pluto[30059]: | ike proposal: AES_CBC_256/HMAC_MD5/MODP_1536,
2011:12:29-08:01:07 lod pluto[30059]: "S_LoD-Home" #2: ike alg: unable to retrieve my private key
2011:12:29-08:01:07 lod pluto[30059]: "S_LoD-Home" #2: empty ISAKMP SA proposal to send (no algorithms for ike selection?)
2011:12:29-08:01:07 lod pluto[30059]: | next event EVENT_SO_DISCARD in 0 seconds for #2
2011:12:29-08:01:07 lod pluto[30059]: |
2011:12:29-08:01:07 lod pluto[30059]: | *time to handle event
2011:12:29-08:01:07 lod pluto[30059]: | event after this is EVENT_REINIT_SECRET in 2952 seconds
2011:12:29-08:01:07 lod pluto[30059]: | ICOOKIE: 32 1d 4b 07 95 c9 58 40
2011:12:29-08:01:07 lod pluto[30059]: | RCOOKIE: 00 00 00 00 00 00 00 00
2011:12:29-08:01:07 lod pluto[30059]: | peer: 50 9c dd d2
2011:12:29-08:01:07 lod pluto[30059]: | state hash entry 2
...


The only way to re-enable the connection is to disable it in the command center, wait about 10/15 minutes and enable it again. Both sides are not using NAT and are set up as initial connections as they are both the local network endpoint. No further router. Is that correct?

Greetinx
LoD


This thread was automatically locked due to age.
Parents
  • I always turn on DPD, and it looks like you need to enable NAT-T, so it's not clear to me why this works at all - are you certain data does flow at times?

    Cheers - Bob
     
    Sophos UTM Community Moderator
    Sophos Certified Architect - UTM
    Sophos Certified Engineer - XG
    Gold Solution Partner since 2005
    MediaSoft, Inc. USA
Reply
  • I always turn on DPD, and it looks like you need to enable NAT-T, so it's not clear to me why this works at all - are you certain data does flow at times?

    Cheers - Bob
     
    Sophos UTM Community Moderator
    Sophos Certified Architect - UTM
    Sophos Certified Engineer - XG
    Gold Solution Partner since 2005
    MediaSoft, Inc. USA
Children
  • Hi Bob,

    yes after dis-and reenabling some times the connection is build. I can easily verify by viewing the ip-phone which is connected to the company's network. Pinging hosts, RDP is also working.

    I'll enable DPD and NAT-T (both sides ?) and report what will happen.

    greetinx
    LoD
  • Hi Bob,

    now I tested the site2site connection with the suggested changes. NAT-T and DPD are enabled on both sites.

    After the change the connection broke and didn't come up again, I waited about an hour. I rebooted the home asg and now for about 20 minutes I'm enabling and disabling die s2s-connection.

    I now enabled all debug messages on the home side. The only error was:

    2011:12:30-04:20:16 lod pluto[17572]: packet from 11.22.33.44:1: initial Main Mode message received on 79.204.164.100:500 but no connection has been authorized with policy=PUBKEY
     


    I then disabled all debug-options, disabled the connection and immidiately enabled it. Now it's up again. 

    I'll wait until 0700 AM to see if it comes back after the internet line reconnection.


    Update: After reconnecting it took about 5 minutes for the command center to contact the ASG Home Edt. I waited further 10 minutes but the connection wasn't established. After disabling and enabling the connection it worked again. Here's the Log:


    2011:12:30-07:10:23 lod pluto[13600]: packet from 11.22.33.44:1: received Vendor ID payload [strongSwan]
    2011:12:30-07:10:23 lod pluto[13600]: packet from 11.22.33.44:1: ignoring Vendor ID payload [Cisco-Unity]
    2011:12:30-07:10:23 lod pluto[13600]: packet from 11.22.33.44:1: received Vendor ID payload [XAUTH]
    2011:12:30-07:10:23 lod pluto[13600]: packet from 11.22.33.44:1: received Vendor ID payload [Dead Peer Detection]
    2011:12:30-07:10:23 lod pluto[13600]: packet from 11.22.33.44:1: received Vendor ID payload [RFC 3947]
    2011:12:30-07:10:23 lod pluto[13600]: packet from 11.22.33.44:1: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03]
    2011:12:30-07:10:23 lod pluto[13600]: packet from 11.22.33.44:1: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02]
    2011:12:30-07:10:23 lod pluto[13600]: packet from 11.22.33.44:1: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n]
    2011:12:30-07:10:23 lod pluto[13600]: packet from 11.22.33.44:1: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-00]
    2011:12:30-07:10:23 lod pluto[13600]: packet from 11.22.33.44:1: initial Main Mode message received on 79.204.174.15:500 but no connection has been authorized with policy=PUBKEY
    2011:12:30-07:11:05 lod pluto[13600]: "S_TuO-Home": deleting connection
    2011:12:30-07:11:05 lod pluto[13600]: "S_TuO-Home" #1: deleting state (STATE_MAIN_I1)
    2011:12:30-07:11:05 lod pluto[13600]: listening for IKE messages
    2011:12:30-07:11:05 lod pluto[13600]: forgetting secrets
    2011:12:30-07:11:05 lod pluto[13600]: loading secrets from "/etc/ipsec.secrets"
    2011:12:30-07:11:05 lod pluto[13600]: loaded PSK secret for 79.204.174.15 %any
    2011:12:30-07:11:05 lod pluto[13600]: forgetting secrets
    2011:12:30-07:11:05 lod pluto[13600]: loading secrets from "/etc/ipsec.secrets"
    2011:12:30-07:11:05 lod pluto[13600]: loaded PSK secret for 79.204.174.15 %any
    ...
    2011:12:30-07:11:06 lod pluto[13600]: packet from 11.22.33.44:500: ignoring Delete SA payload: not encrypted
    2011:12:30-07:11:13 lod pluto[13600]: listening for IKE messages
    2011:12:30-07:11:13 lod pluto[13600]: forgetting secrets
    2011:12:30-07:11:13 lod pluto[13600]: loading secrets from "/etc/ipsec.secrets"
    2011:12:30-07:11:13 lod pluto[13600]: loaded PSK secret for 79.204.174.15 %any
    2011:12:30-07:11:13 lod pluto[13600]: added connection description "S_TuO-Home"
    2011:12:30-07:11:13 lod pluto[13600]: "S_TuO-Home" #2: initiating Main Mode
    2011:12:30-07:11:13 lod pluto[13600]: forgetting secrets
    2011:12:30-07:11:13 lod pluto[13600]: loading secrets from "/etc/ipsec.secrets"
    2011:12:30-07:11:13 lod pluto[13600]: loaded PSK secret for 79.204.174.15 %any
    ...
    2011:12:30-07:11:13 lod pluto[13600]: Changing to directory '/etc/ipsec.d/crls'
    2011:12:30-07:11:13 lod pluto[13600]: packet from 11.22.33.44:500: ignoring informational payload, type NO_PROPOSAL_CHOSEN
    2011:12:30-07:12:36 lod pluto[13600]: packet from 11.22.33.44:500: ignoring Delete SA payload: not encrypted
    2011:12:30-07:12:41 lod pluto[13600]: "S_TuO-Home": deleting connection
    2011:12:30-07:12:41 lod pluto[13600]: "S_TuO-Home" #2: deleting state (STATE_MAIN_I1)
    2011:12:30-07:12:41 lod pluto[13600]: listening for IKE messages
    2011:12:30-07:12:41 lod pluto[13600]: forgetting secrets
    2011:12:30-07:12:41 lod pluto[13600]: loading secrets from "/etc/ipsec.secrets"
    2011:12:30-07:12:41 lod pluto[13600]: loaded PSK secret for 79.204.174.15 %any
    2011:12:30-07:12:41 lod pluto[13600]: forgetting secrets
    2011:12:30-07:12:41 lod pluto[13600]: loading secrets from "/etc/ipsec.secrets"
    ...
    2011:12:30-07:12:41 lod pluto[13600]: Changing to directory '/etc/ipsec.d/crls'
    2011:12:30-07:15:11 lod pluto[13600]: added connection description "S_TuO-Home"
    2011:12:30-07:15:11 lod pluto[13600]: "S_TuO-Home" #3: initiating Main Mode
    2011:12:30-07:15:11 lod pluto[13600]: "S_TuO-Home" #3: ike alg: unable to retrieve my private key
    2011:12:30-07:15:11 lod pluto[13600]: "S_TuO-Home" #3: empty ISAKMP SA proposal to send (no algorithms for ike selection?)
    2011:12:30-07:15:11 lod pluto[13600]: listening for IKE messages
    2011:12:30-07:15:11 lod pluto[13600]: forgetting secrets
    2011:12:30-07:15:11 lod pluto[13600]: loading secrets from "/etc/ipsec.secrets"
    2011:12:30-07:15:11 lod pluto[13600]: loaded PSK secret for 79.204.174.15 %any
    2011:12:30-07:15:11 lod pluto[13600]: forgetting secrets
    2011:12:30-07:15:11 lod pluto[13600]: loading secrets from "/etc/ipsec.secrets"
    2011:12:30-07:15:11 lod pluto[13600]: loaded PSK secret for 79.204.174.15 %any
    2011:12:30-07:15:11 lod pluto[13600]: loading ca certificates from '/etc/ipsec.d/cacerts'
    2011:12:30-07:15:11 lod pluto[13600]: loaded ca certificate from '/etc/ipsec.d/cacerts/VPN Signing CA.pem'
    2011:12:30-07:15:11 lod pluto[13600]: loading aa certificates from '/etc/ipsec.d/aacerts'
    2011:12:30-07:15:11 lod pluto[13600]: loading ocsp certificates from '/etc/ipsec.d/ocspcerts'
    2011:12:30-07:15:11 lod pluto[13600]: loading attribute certificates from '/etc/ipsec.d/acerts'
    2011:12:30-07:15:11 lod pluto[13600]: Changing to directory '/etc/ipsec.d/crls'
    2011:12:30-07:15:11 lod pluto[13600]: packet from 11.22.33.44:1: received Vendor ID payload [strongSwan]
    2011:12:30-07:15:11 lod pluto[13600]: packet from 11.22.33.44:1: ignoring Vendor ID payload [Cisco-Unity]
    2011:12:30-07:15:11 lod pluto[13600]: packet from 11.22.33.44:1: received Vendor ID payload [XAUTH]
    2011:12:30-07:15:11 lod pluto[13600]: packet from 11.22.33.44:1: received Vendor ID payload [Dead Peer Detection]
    2011:12:30-07:15:11 lod pluto[13600]: packet from 11.22.33.44:1: received Vendor ID payload [RFC 3947]
    2011:12:30-07:15:11 lod pluto[13600]: packet from 11.22.33.44:1: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03]
    2011:12:30-07:15:11 lod pluto[13600]: packet from 11.22.33.44:1: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02]
    2011:12:30-07:15:11 lod pluto[13600]: packet from 11.22.33.44:1: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n]
    2011:12:30-07:15:11 lod pluto[13600]: packet from 11.22.33.44:1: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-00]
    2011:12:30-07:15:11 lod pluto[13600]: packet from 11.22.33.44:1: initial Main Mode message received on 79.204.174.15:500 but no connection has been authorized with policy=PUBKEY
    ... 3x ...
    2011:12:30-07:16:21 lod pluto[13600]: packet from 11.22.33.44:500: received Vendor ID payload [strongSwan]
    2011:12:30-07:16:21 lod pluto[13600]: packet from 11.22.33.44:500: ignoring Vendor ID payload [Cisco-Unity]
    2011:12:30-07:16:21 lod pluto[13600]: packet from 11.22.33.44:500: received Vendor ID payload [XAUTH]
    2011:12:30-07:16:21 lod pluto[13600]: packet from 11.22.33.44:500: received Vendor ID payload [Dead Peer Detection]
    2011:12:30-07:16:21 lod pluto[13600]: packet from 11.22.33.44:500: received Vendor ID payload [RFC 3947]
    2011:12:30-07:16:21 lod pluto[13600]: packet from 11.22.33.44:500: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03]
    2011:12:30-07:16:21 lod pluto[13600]: packet from 11.22.33.44:500: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02]
    2011:12:30-07:16:21 lod pluto[13600]: packet from 11.22.33.44:500: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n]
    2011:12:30-07:16:21 lod pluto[13600]: packet from 11.22.33.44:500: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-00]
    2011:12:30-07:16:21 lod pluto[13600]: "S_TuO-Home" #4: responding to Main Mode
    2011:12:30-07:16:21 lod pluto[13600]: "S_TuO-Home" #4: NAT-Traversal: Result using RFC 3947: no NAT detected
    2011:12:30-07:16:21 lod pluto[13600]: "S_TuO-Home" #4: Peer ID is ID_IPV4_ADDR: '11.22.33.44'
    2011:12:30-07:16:21 lod pluto[13600]: "S_TuO-Home" #4: we don't have a cert
    2011:12:30-07:16:21 lod pluto[13600]: "S_TuO-Home" #4: Dead Peer Detection (RFC 3706) enabled
    2011:12:30-07:16:21 lod pluto[13600]: "S_TuO-Home" #4: sent MR3, ISAKMP SA established
    2011:12:30-07:16:21 lod pluto[13600]: "S_TuO-Home" #5: responding to Quick Mode
    2011:12:30-07:16:22 lod pluto[13600]: "S_TuO-Home" #5: IPsec SA established {ESP=>0x92b3c0a2 



    regards,

    LoD