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

0 BAlfson over 12 years ago

You said that both sides were not using NAT, but your first post included 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, so I'm confused about that part.

In your update to Post #4, it looks like the two sides can't agree on the policy/PSK. It would be interesting to see the log for the same connection attempt from the other side.

If 'Enable probing of preshared keys' produces a successful test, I wonder if this isn't an ACC issue. What happens if you configure the VPN directly on the two Astaros instead of with the ACC?

Cheers - Bob

Sophos UTM Community Moderator
Sophos Certified Architect - UTM
Sophos Certified Engineer - XG
Gold Solution Partner since 2005

MediaSoft, Inc. USA
Cancel
Vote Up 0 Vote Down

Cancel
0 LoD over 12 years ago in reply to BAlfson

Hi Bob and a happy new year to you!

I deleted the s2s-connection in CC-Admin and created them manually. Connection was established immediately but broke after about half an hour not comming up again.

The first interessting point while logging the ASG 220-side is this entry, I guess.

2012:01:01-21:10:28 mail ipsec_starter[8110]: no default route - cannot cope with %defaultroute!!!

No further errors occured. In fact on the ASG 220-side there are two internet connections: one for VPN the other one for web surfing and so on. The second one is the default gw while the "VPN-IP" isn't.

Might that be the problem? Where can I check this?

greetinx
LoD
Cancel
Vote Up 0 Vote Down

Cancel
0 LoD over 12 years ago in reply to LoD

Hi there,

I now tried to setup the vpn using the command center and recognized that the settings are only applied to the ASG not to the software side.

Where can I get some logs concerning the command center? I search the WebAdmin of the CC but didn't find any clue.

Second: On the command center -> Management -> Registration the public IP of the home edition differs from the Agent IP.

Might that be the cause? If it is: How can I fix that?

Greetinx
LoD
Cancel
Vote Up 0 Vote Down

Cancel

Reply

0 LoD over 12 years ago in reply to LoD

Hi there,

I now tried to setup the vpn using the command center and recognized that the settings are only applied to the ASG not to the software side.

Where can I get some logs concerning the command center? I search the WebAdmin of the CC but didn't find any clue.

Second: On the command center -> Management -> Registration the public IP of the home edition differs from the Agent IP.

Might that be the cause? If it is: How can I fix that?

Greetinx
LoD
Cancel
Vote Up 0 Vote Down

Cancel

Children

No Data