Thread Info
  • State Not Answered
  • Locked Locked
  • Replies 1 reply
  • Subscribers 2 subscribers
  • Views 2446 views
  • Users 0 members are here
Options
Suggested
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

IPSec Tunnel won't connect error - cannot respond to IPsec SA request

Nathon Johnson

Hello, long time lurker first-time poster here. I'm working to rebuild an IPsec tunnel. The remote end (third party ISP) and we are seeing the following in the UTM logs and the SA entry is never created. 

 

I'm wondering, would having the remote side set the tunnel to repsond only help? if not what should be done to restore the tunnel? 

 

The messages below repeat every 60 seconds. 

2019:02:15-14:12:32 utmpw pluto[13408]: | *received 172 bytes from 64.47.XXX.XXX:500 on eth7
2019:02:15-14:12:32 utmpw pluto[13408]: | **parse ISAKMP Message:
2019:02:15-14:12:32 utmpw pluto[13408]: | initiator cookie:
2019:02:15-14:12:32 utmpw pluto[13408]: | 4f db 1d 10 4a 8e 72 af
2019:02:15-14:12:32 utmpw pluto[13408]: | responder cookie:
2019:02:15-14:12:32 utmpw pluto[13408]: | 64 a4 bf c8 af 1e 48 10
2019:02:15-14:12:32 utmpw pluto[13408]: | next payload type: ISAKMP_NEXT_HASH
2019:02:15-14:12:32 utmpw pluto[13408]: | ISAKMP version: ISAKMP Version 1.0
2019:02:15-14:12:32 utmpw pluto[13408]: | exchange type: ISAKMP_XCHG_QUICK
2019:02:15-14:12:32 utmpw pluto[13408]: | flags: ISAKMP_FLAG_ENCRYPTION
2019:02:15-14:12:32 utmpw pluto[13408]: | message ID: 3e b5 8a f4
2019:02:15-14:12:32 utmpw pluto[13408]: | length: 172
2019:02:15-14:12:32 utmpw pluto[13408]: | ICOOKIE: 4f db 1d 10 4a 8e 72 af
2019:02:15-14:12:32 utmpw pluto[13408]: | RCOOKIE: 64 a4 bf c8 af 1e 48 10
2019:02:15-14:12:32 utmpw pluto[13408]: | peer: 40 2f 5b 22
2019:02:15-14:12:32 utmpw pluto[13408]: | state hash entry 0
2019:02:15-14:12:32 utmpw pluto[13408]: | state object not found
2019:02:15-14:12:32 utmpw pluto[13408]: | ICOOKIE: 4f db 1d 10 4a 8e 72 af
2019:02:15-14:12:32 utmpw pluto[13408]: | RCOOKIE: 64 a4 bf c8 af 1e 48 10
2019:02:15-14:12:32 utmpw pluto[13408]: | peer: 40 2f 5b 22
2019:02:15-14:12:32 utmpw pluto[13408]: | state hash entry 0
2019:02:15-14:12:32 utmpw pluto[13408]: | state object #65420 found, in STATE_MAIN_R3
2019:02:15-14:12:32 utmpw pluto[13408]: | ***parse ISAKMP Hash Payload:
2019:02:15-14:12:32 utmpw pluto[13408]: | next payload type: ISAKMP_NEXT_SA
2019:02:15-14:12:32 utmpw pluto[13408]: | length: 24
2019:02:15-14:12:32 utmpw pluto[13408]: | ***parse ISAKMP Security Association Payload:
2019:02:15-14:12:32 utmpw pluto[13408]: | next payload type: ISAKMP_NEXT_NONCE
2019:02:15-14:12:32 utmpw pluto[13408]: | length: 52
2019:02:15-14:12:32 utmpw pluto[13408]: | DOI: ISAKMP_DOI_IPSEC
2019:02:15-14:12:32 utmpw pluto[13408]: | ***parse ISAKMP Nonce Payload:
2019:02:15-14:12:32 utmpw pluto[13408]: | next payload type: ISAKMP_NEXT_ID
2019:02:15-14:12:32 utmpw pluto[13408]: | length: 20
2019:02:15-14:12:32 utmpw pluto[13408]: | ***parse ISAKMP Identification Payload (IPsec DOI):
2019:02:15-14:12:32 utmpw pluto[13408]: | next payload type: ISAKMP_NEXT_ID
2019:02:15-14:12:32 utmpw pluto[13408]: | length: 16
2019:02:15-14:12:32 utmpw pluto[13408]: | ID type: ID_IPV4_ADDR_SUBNET
2019:02:15-14:12:32 utmpw pluto[13408]: | Protocol ID: 0
2019:02:15-14:12:32 utmpw pluto[13408]: | port: 0
2019:02:15-14:12:32 utmpw pluto[13408]: | ***parse ISAKMP Identification Payload (IPsec DOI):
2019:02:15-14:12:32 utmpw pluto[13408]: | next payload type: ISAKMP_NEXT_NONE
2019:02:15-14:12:32 utmpw pluto[13408]: | length: 16
2019:02:15-14:12:32 utmpw pluto[13408]: | ID type: ID_IPV4_ADDR_SUBNET
2019:02:15-14:12:32 utmpw pluto[13408]: | Protocol ID: 0
2019:02:15-14:12:32 utmpw pluto[13408]: | port: 0
2019:02:15-14:12:32 utmpw pluto[13408]: | removing 16 bytes of padding
2019:02:15-14:12:32 utmpw pluto[13408]: | peer client is subnet 0.0.0.0/0
2019:02:15-14:12:32 utmpw pluto[13408]: | peer client protocol/port is 0/0
2019:02:15-14:12:32 utmpw pluto[13408]: | our client is subnet 0.0.0.0/0
2019:02:15-14:12:32 utmpw pluto[13408]: | our client protocol/port is 0/0
2019:02:15-14:12:32 utmpw pluto[13408]: | find_client_connection starting with S_REF_IpsSitAlfreadvpn_4
2019:02:15-14:12:32 utmpw pluto[13408]: | looking for 0.0.0.0/0:0/0 -> 192.168.230.0/23:0/0
2019:02:15-14:12:32 utmpw pluto[13408]: | concrete checking against sr#0 10.16.0.0/13 -> 192.168.230.0/23
2019:02:15-14:12:32 utmpw pluto[13408]: | fc_try trying S_REF_IpsSitAlfreadvpn_4:0.0.0.0/0:0/0 -> 192.168.230.0/23:0/0 vs S_REF_IpsSitAlfreadvpn_4:10.16.0.0/13:0/0 -> 192.168.230.0/23:0/0
2019:02:15-14:12:32 utmpw pluto[13408]: | fc_try trying S_REF_IpsSitAlfreadvpn_4:0.0.0.0/0:0/0 -> 192.168.230.0/23:0/0 vs S_REF_IpsSitAlfreadvpn_3:10.16.0.0/13:0/0 -> 192.168.204.0/23:0/0
2019:02:15-14:12:32 utmpw pluto[13408]: | fc_try trying S_REF_IpsSitAlfreadvpn_4:0.0.0.0/0:0/0 -> 192.168.230.0/23:0/0 vs S_REF_IpsSitAlfreadvpn_2:10.16.0.0/13:0/0 -> 192.168.200.0/23:0/0
2019:02:15-14:12:32 utmpw pluto[13408]: | fc_try trying S_REF_IpsSitAlfreadvpn_4:0.0.0.0/0:0/0 -> 192.168.230.0/23:0/0 vs S_REF_IpsSitAlfreadvpn_1:10.16.0.0/13:0/0 -> 192.168.200.5/32:0/0
2019:02:15-14:12:32 utmpw pluto[13408]: | fc_try trying S_REF_IpsSitAlfreadvpn_4:0.0.0.0/0:0/0 -> 192.168.230.0/23:0/0 vs S_REF_IpsSitAlfreadvpn_0:10.16.0.0/13:0/0 -> 192.168.200.3/32:0/0
2019:02:15-14:12:32 utmpw pluto[13408]: | fc_try concluding with none [0]
2019:02:15-14:12:32 utmpw pluto[13408]: | fc_try S_REF_IpsSitAlfreadvpn_4 gives none
2019:02:15-14:12:32 utmpw pluto[13408]: | checking hostpair 10.16.0.0/13 -> 192.168.230.0/23 is not found
2019:02:15-14:12:32 utmpw pluto[13408]: | concluding with d = none
2019:02:15-14:12:32 utmpw pluto[13408]: "S_REF_IpsSitAlfreadvpn_4" #65420: cannot respond to IPsec SA request because no connection is known for 0.0.0.0/0===50.200.XXX.XXX[50.200.XXX.XXX]...64.47.XXX.XXX[64.47.XXX.XXX]===192.168.230.0/23
2019:02:15-14:12:32 utmpw pluto[13408]: "S_REF_IpsSitAlfreadvpn_4" #65420: sending encrypted notification INVALID_ID_INFORMATION to 64.47.XXX.XXX:500
2019:02:15-14:12:32 utmpw pluto[13408]: | **emit ISAKMP Message:
2019:02:15-14:12:32 utmpw pluto[13408]: | initiator cookie:
2019:02:15-14:12:32 utmpw pluto[13408]: | 4f db 1d 10 4a 8e 72 af
2019:02:15-14:12:32 utmpw pluto[13408]: | responder cookie:
2019:02:15-14:12:32 utmpw pluto[13408]: | 64 a4 bf c8 af 1e 48 10
2019:02:15-14:12:32 utmpw pluto[13408]: | next payload type: ISAKMP_NEXT_HASH
2019:02:15-14:12:32 utmpw pluto[13408]: | ISAKMP version: ISAKMP Version 1.0
2019:02:15-14:12:32 utmpw pluto[13408]: | exchange type: ISAKMP_XCHG_INFO
2019:02:15-14:12:32 utmpw pluto[13408]: | flags: ISAKMP_FLAG_ENCRYPTION
2019:02:15-14:12:32 utmpw pluto[13408]: | message ID: 1a a3 12 35
2019:02:15-14:12:32 utmpw pluto[13408]: | ***emit ISAKMP Hash Payload:
2019:02:15-14:12:32 utmpw pluto[13408]: | next payload type: ISAKMP_NEXT_N
2019:02:15-14:12:32 utmpw pluto[13408]: | emitting 20 zero bytes of HASH into ISAKMP Hash Payload
2019:02:15-14:12:32 utmpw pluto[13408]: | emitting length of ISAKMP Hash Payload: 24
2019:02:15-14:12:32 utmpw pluto[13408]: | ***emit ISAKMP Notification Payload:
2019:02:15-14:12:32 utmpw pluto[13408]: | next payload type: ISAKMP_NEXT_NONE
2019:02:15-14:12:32 utmpw pluto[13408]: | DOI: ISAKMP_DOI_IPSEC
2019:02:15-14:12:32 utmpw pluto[13408]: | protocol ID: 1
2019:02:15-14:12:32 utmpw pluto[13408]: | SPI size: 0
2019:02:15-14:12:32 utmpw pluto[13408]: | Notify Message Type: INVALID_ID_INFORMATION
2019:02:15-14:12:32 utmpw pluto[13408]: | emitting 0 raw bytes of spi into ISAKMP Notification Payload
2019:02:15-14:12:32 utmpw pluto[13408]: | spi
2019:02:15-14:12:32 utmpw pluto[13408]: | emitting length of ISAKMP Notification Payload: 12
2019:02:15-14:12:32 utmpw pluto[13408]: | emitting 12 zero bytes of encryption padding into ISAKMP Message
2019:02:15-14:12:32 utmpw pluto[13408]: | emitting length of ISAKMP Message: 76
2019:02:15-14:12:32 utmpw pluto[13408]: | state transition function for STATE_QUICK_R0 failed: INVALID_ID_INFORMATION
2019:02:15-14:12:32 utmpw pluto[13408]: | next event EVENT_DPD in 2 seconds for #65159
2019:02:15-14:12:34 utmpw pluto[13408]: |
2019:02:15-14:12:34 utmpw pluto[13408]: | *received 172 bytes from 64.47.XXX.XXX:500 on eth7
2019:02:15-14:12:34 utmpw pluto[13408]: | **parse ISAKMP Message:
2019:02:15-14:12:34 utmpw pluto[13408]: | initiator cookie:
2019:02:15-14:12:34 utmpw pluto[13408]: | 4f db 1d 10 4a 8e 72 af
2019:02:15-14:12:34 utmpw pluto[13408]: | responder cookie:
2019:02:15-14:12:34 utmpw pluto[13408]: | 64 a4 bf c8 af 1e 48 10
2019:02:15-14:12:34 utmpw pluto[13408]: | next payload type: ISAKMP_NEXT_HASH
2019:02:15-14:12:34 utmpw pluto[13408]: | ISAKMP version: ISAKMP Version 1.0
2019:02:15-14:12:34 utmpw pluto[13408]: | exchange type: ISAKMP_XCHG_QUICK
2019:02:15-14:12:34 utmpw pluto[13408]: | flags: ISAKMP_FLAG_ENCRYPTION
2019:02:15-14:12:34 utmpw pluto[13408]: | message ID: 3e b5 8a f4
2019:02:15-14:12:34 utmpw pluto[13408]: | length: 172
2019:02:15-14:12:34 utmpw pluto[13408]: | ICOOKIE: 4f db 1d 10 4a 8e 72 af
2019:02:15-14:12:34 utmpw pluto[13408]: | RCOOKIE: 64 a4 bf c8 af 1e 48 10
2019:02:15-14:12:34 utmpw pluto[13408]: | peer: 40 2f 5b 22
2019:02:15-14:12:34 utmpw pluto[13408]: | state hash entry 0
2019:02:15-14:12:34 utmpw pluto[13408]: | state object not found
2019:02:15-14:12:34 utmpw pluto[13408]: | ICOOKIE: 4f db 1d 10 4a 8e 72 af
2019:02:15-14:12:34 utmpw pluto[13408]: | RCOOKIE: 64 a4 bf c8 af 1e 48 10
2019:02:15-14:12:34 utmpw pluto[13408]: | peer: 40 2f 5b 22
2019:02:15-14:12:34 utmpw pluto[13408]: | state hash entry 0
2019:02:15-14:12:34 utmpw pluto[13408]: | state object #65420 found, in STATE_MAIN_R3
2019:02:15-14:12:34 utmpw pluto[13408]: "S_REF_IpsSitAlfreadvpn_4" #65420: Quick Mode I1 message is unacceptable because it uses a previously used Message ID 0xf48ab53e (perhaps this is a duplicated packet)
2019:02:15-14:12:34 utmpw pluto[13408]: "S_REF_IpsSitAlfreadvpn_4" #65420: sending encrypted notification INVALID_MESSAGE_ID to 64.47.XXX.XXX:500
2019:02:15-14:12:34 utmpw pluto[13408]: | **emit ISAKMP Message:
2019:02:15-14:12:34 utmpw pluto[13408]: | initiator cookie:
2019:02:15-14:12:34 utmpw pluto[13408]: | 4f db 1d 10 4a 8e 72 af
2019:02:15-14:12:34 utmpw pluto[13408]: | responder cookie:
2019:02:15-14:12:34 utmpw pluto[13408]: | 64 a4 bf c8 af 1e 48 10
2019:02:15-14:12:34 utmpw pluto[13408]: | next payload type: ISAKMP_NEXT_HASH
2019:02:15-14:12:34 utmpw pluto[13408]: | ISAKMP version: ISAKMP Version 1.0
2019:02:15-14:12:34 utmpw pluto[13408]: | exchange type: ISAKMP_XCHG_INFO
2019:02:15-14:12:34 utmpw pluto[13408]: | flags: ISAKMP_FLAG_ENCRYPTION
2019:02:15-14:12:34 utmpw pluto[13408]: | message ID: f2 65 a2 fe
2019:02:15-14:12:34 utmpw pluto[13408]: | ***emit ISAKMP Hash Payload:
2019:02:15-14:12:34 utmpw pluto[13408]: | next payload type: ISAKMP_NEXT_N
2019:02:15-14:12:34 utmpw pluto[13408]: | emitting 20 zero bytes of HASH into ISAKMP Hash Payload
2019:02:15-14:12:34 utmpw pluto[13408]: | emitting length of ISAKMP Hash Payload: 24
2019:02:15-14:12:34 utmpw pluto[13408]: | ***emit ISAKMP Notification Payload:
2019:02:15-14:12:34 utmpw pluto[13408]: | next payload type: ISAKMP_NEXT_NONE
2019:02:15-14:12:34 utmpw pluto[13408]: | DOI: ISAKMP_DOI_IPSEC
2019:02:15-14:12:34 utmpw pluto[13408]: | protocol ID: 1
2019:02:15-14:12:34 utmpw pluto[13408]: | SPI size: 0
2019:02:15-14:12:34 utmpw pluto[13408]: | Notify Message Type: INVALID_MESSAGE_ID
2019:02:15-14:12:34 utmpw pluto[13408]: | emitting 0 raw bytes of spi into ISAKMP Notification Payload
2019:02:15-14:12:34 utmpw pluto[13408]: | spi
2019:02:15-14:12:34 utmpw pluto[13408]: | emitting length of ISAKMP Notification Payload: 12
2019:02:15-14:12:34 utmpw pluto[13408]: | emitting 12 zero bytes of encryption padding into ISAKMP Message
2019:02:15-14:12:34 utmpw pluto[13408]: | emitting length of ISAKMP Message: 76
2019:02:15-14:12:34 utmpw pluto[13408]: | next event EVENT_DPD in 0 seconds for #65159
2019:02:15-14:12:34 utmpw pluto[13408]: |
2019:02:15-14:12:34 utmpw pluto[13408]: | *time to handle event
2019:02:15-14:12:34 utmpw pluto[13408]: | event after this is EVENT_DPD_UPDATE in 0 seconds
2019:02:15-14:12:34 utmpw pluto[13408]: | recent DPD activity 10 seconds ago, no need to send DPD notification
2019:02:15-14:12:34 utmpw pluto[13408]: | inserting event EVENT_DPD, timeout in 30 seconds for #65159
2019:02:15-14:12:34 utmpw pluto[13408]: | next event EVENT_DPD_UPDATE in 0 seconds for #65414
2019:02:15-14:12:34 utmpw pluto[13408]: |



This thread was automatically locked due to age.
  • 0

    Hi Nathon - welcome to the UTM Community!

    That's just too hard to read and doesn't provide the necessary information.  Please edit your post and replace the log lines with the following:

    1. Confirm that Debug is not enabled.
    2. Disable the IPsec Connection.
    3. Start the IPsec Live Log and wait for it to begin to populate.
    4. Enable the IPsec Connection.
    5. Show us about 60 lines from enabling through the error.

    Cheers - Bob

     
    Sophos UTM Community Moderator
    Sophos Certified Architect - UTM
    Sophos Certified Engineer - XG
    Gold Solution Partner since 2005
    MediaSoft, Inc. USA
Unfiltered HTML