Droped outbound IPSec packets; :500 failed in main_outI1. Errno 1 Operation not permitted

Hello,

 

I'm having a hard time trying to establish a new VPN tunnel from my UTM 220 (Firmware version: 9.508-10) to an ASA 5525.

We have many IPSec tunnels, which are working on this device... but not the latter.

I get the following ERROR: "S_UT**" #41: sendto on eth2 to 196.****:500 failed in main_outI1. Errno 1: Operation not permitted

I triple checked all IKE parameters, PSK, etc and they're ok.

All the interfaces in question (remote network, remote gateway) are not bound to a specific interface. (left with "any')

On the UTM side we NAT to a public IP.

The thing is that we receive the remote peer's packets (as seen on debugging_log), but the outbound packets get dropped by the firewall.

ulogd[5464]: id="2001" severity="info" sys="SecureNet" sub="packetfilter" name="Packet dropped" action="drop" fwrule="60003" outitf="eth1" srcmac="00:1a::):f0:f3:41" srcip="9.XXXXX" dstip="196.XXXXXX" proto="17" length="288" tos="0x00" prec="0x00" ttl="64" srcport="500" dstport="500"

I attached firewall and IP-Sec logs

I don't understand where is the problem... what is blocking the packets.

 

Thank you!

  • Salut Gery and welcome to the UTM Community!

    Alone among the logs, the Firewall Live Log presents abbreviated information in a format easier to read quickly.  Usually, you can't troubleshoot without looking at the corresponding line from the full Firewall log file.  Please post the line corresponding to that above.

    Instead of pictures, please copy the log lines into here.  Obfuscate private information like 50.x.y.101, 10.x.y.23 and domain.com.

    Also for the IPsec log:

    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.

    Is anti-replay enabled on the ASA?  That's a non-starter with the UTM's IPsec implementation.

    Make sure that the DPD and NAT-T settings are both on in both the UTM and the ASA.

    Cheers - Bob

  • In reply to BAlfson:

    Hi Bob,

     

    The corresponding line from the full Firewall log is below:

    2018:04:16-12:43:24 -1 ulogd[5464]: id="2001" severity="info" sys="SecureNet" sub="packetfilter" name="Packet dropped" action="drop" fwrule="60003" outitf="eth1" 
    srcmac="00:1a:)):f0:f3:41" srcip="91.x.y.13" dstip="196.x.y.35" proto="17" length="288" tos="0x00" prec="0x00" ttl="64" srcport="500" dstport="500"


    and the IPsec log wo debug

    2018:04:16-12:43:22 fw1-2 pluto[26255]: forgetting secrets

    2018:04:16-12:43:22 fw1-2 pluto[26255]: loading secrets from "/etc/ipsec.secrets"

    2018:04:16-12:43:22 fw1-2 pluto[26255]: loaded PSK secret for 91.x.y.3 196.x.y.35

    2018:04:16-12:43:22 fw1-2 pluto[26255]: loaded PSK secret for 91.x.y.3 91.x.y.6

    2018:04:16-12:43:22 fw1-2 pluto[26255]: HA System: not master, won't listen for IKE messages

    2018:04:16-12:43:22 fw1-2 pluto[26255]: forgetting secrets

    2018:04:16-12:43:22 fw1-2 pluto[26255]: loading secrets from "/etc/ipsec.secrets"

    2018:04:16-12:43:22 fw1-2 pluto[26255]: loaded PSK secret for 91.x.y.3 5.x.y.66

    2018:04:16-12:43:22 fw1-2 pluto[26255]: loaded PSK secret for 91.x.y.3 196.x.y.35

    2018:04:16-12:43:22 fw1-2 pluto[26255]: loaded PSK secret for 91.x.y.3 91.x.y.6

    2018:04:16-12:43:22 fw1-2 pluto[26255]: loading ca certificates from '/etc/ipsec.d/cacerts'

    2018:04:16-12:43:22 fw1-2 pluto[26255]: loaded ca certificate from '/etc/ipsec.d/cacerts/VPN Signing CA.pem'

    2018:04:16-12:43:22 fw1-2 pluto[26255]: loading aa certificates from '/etc/ipsec.d/aacerts'

    2018:04:16-12:43:22 fw1-2 pluto[26255]: loading ocsp certificates from '/etc/ipsec.d/ocspcerts'

    2018:04:16-12:43:22 fw1-2 pluto[26255]: loading attribute certificates from '/etc/ipsec.d/acerts'

    2018:04:16-12:43:22 fw1-2 pluto[26255]: Changing to directory '/etc/ipsec.d/crls'

    2018:04:16-12:43:22 fw1-2 pluto[26255]: added connection description "S_I"

    2018:04:16-12:43:23 fw1-1 pluto[5746]: forgetting secrets

    2018:04:16-12:43:23 fw1-1 pluto[5746]: loading secrets from "/etc/ipsec.secrets"

    2018:04:16-12:43:23 fw1-1 pluto[5746]: loaded PSK secret for 91.x.y.3 196.x.y.35

    2018:04:16-12:43:23 fw1-1 pluto[5746]: loaded PSK secret for 91.x.y.3 91.x.y.6

    2018:04:16-12:43:23 fw1-1 pluto[5746]: listening for IKE messages

    2018:04:16-12:43:23 fw1-1 pluto[5746]: forgetting secrets

    2018:04:16-12:43:23 fw1-1 pluto[5746]: loading secrets from "/etc/ipsec.secrets"

    2018:04:16-12:43:23 fw1-1 pluto[5746]: loaded PSK secret for 91.x.y.3 94.x.y.149

    2018:04:16-12:43:23 fw1-1 pluto[5746]: loaded PSK secret for 91.x.y.3 196.x.y.35

    2018:04:16-12:43:23 fw1-1 pluto[5746]: loaded PSK secret for 91.x.y.3 91.x.y.6

    2018:04:16-12:43:23 fw1-1 pluto[5746]: loading ca certificates from '/etc/ipsec.d/cacerts'

    2018:04:16-12:43:23 fw1-1 pluto[5746]: loaded ca certificate from '/etc/ipsec.d/cacerts/VPN Signing CA.pem'

    2018:04:16-12:43:23 fw1-1 pluto[5746]: loading aa certificates from '/etc/ipsec.d/aacerts'

    2018:04:16-12:43:23 fw1-1 pluto[5746]: loading ocsp certificates from '/etc/ipsec.d/ocspcerts'

    2018:04:16-12:43:23 fw1-1 pluto[5746]: loading attribute certificates from '/etc/ipsec.d/acerts'

    2018:04:16-12:43:23 fw1-1 pluto[5746]: Changing to directory '/etc/ipsec.d/crls'

    2018:04:16-12:43:23 fw1-1 pluto[5746]: added connection description "S_I"

    2018:04:16-12:43:23 fw1-1 pluto[5746]: "S_I" #3397: initiating Main Mode

    2018:04:16-12:43:23 fw1-1 pluto[5746]: ERROR: "S_I" #3397: sendto on eth2 to 196.x.y.35:500 failed in main_outI1. Errno 1: Operation not permitted

    2018:04:16-12:43:33 fw1-1 pluto[5746]: "S_I" #3397: ignoring Vendor ID payload [FRAGMENTATION c0000000]

    2018:04:16-12:43:33 fw1-1 pluto[5746]: "S_I" #3397: ignoring Vendor ID payload [Cisco-Unity]

    2018:04:16-12:43:33 fw1-1 pluto[5746]: "S_I" #3397: received Vendor ID payload [XAUTH]

    2018:04:16-12:43:33 fw1-1 pluto[5746]: "S_I" #3397: ignoring Vendor ID payload [c4e63313bf33cb39c0f79eed66412d51]

    2018:04:16-12:43:33 fw1-1 pluto[5746]: "S_I" #3397: ignoring Vendor ID payload [Cisco VPN 3000 Series]

    2018:04:16-12:43:33 fw1-1 pluto[5746]: "S_I" #3397: received Vendor ID payload [Dead Peer Detection]

    2018:04:16-12:43:33 fw1-1 pluto[5746]: "S_I" #3397: Peer ID is ID_IPV4_ADDR: '196.x.y.35'

    2018:04:16-12:43:33 fw1-1 pluto[5746]: "S_I" #3397: Dead Peer Detection (RFC 3706) enabled

    2018:04:16-12:43:33 fw1-1 pluto[5746]: "S_I" #3397: ISAKMP SA established

    2018:04:16-12:43:33 fw1-1 pluto[5746]: "S_I" #3398: initiating Quick Mode PSK+ENCRYPT+TUNNEL+UP {using isakmp#3397}

    2018:04:16-12:43:34 fw1-1 pluto[5746]: "S_I" #3397: ignoring informational payload, type NO_PROPOSAL_CHOSEN

    2018:04:16-12:43:34 fw1-1 pluto[5746]: "S_I" #3397: received Delete SA payload: deleting ISAKMP State #3397

    2018:04:16-12:43:40 fw1-1 pluto[5746]: packet from 62.x.y.234:500: ignoring informational payload, type NO_PROPOSAL_CHOSEN

     

    DPD and NAT-T are both enabled.

    I will check the anti-replay as well.

     

    Thank you.

  • In reply to Gery:

    here is another one with both DPD and NAT-T enabled

    also anti-replay is disabled on the ASA

     

    2018:04:16-17:22:49 fw1-1 pluto[5746]: loaded PSK secret for 91.x.y.13 91.x.y.6

    2018:04:16-17:22:49 fw1-1 pluto[5746]: loading ca certificates from '/etc/ipsec.d/cacerts'

    2018:04:16-17:22:49 fw1-1 pluto[5746]: loaded ca certificate from '/etc/ipsec.d/cacerts/VPN Signing CA.pem'

    2018:04:16-17:22:49 fw1-1 pluto[5746]: loading aa certificates from '/etc/ipsec.d/aacerts'

    2018:04:16-17:22:49 fw1-1 pluto[5746]: loading ocsp certificates from '/etc/ipsec.d/ocspcerts'

    2018:04:16-17:22:49 fw1-1 pluto[5746]: loading attribute certificates from '/etc/ipsec.d/acerts'

    2018:04:16-17:22:49 fw1-1 pluto[5746]: Changing to directory '/etc/ipsec.d/crls'

    2018:04:16-17:22:49 fw1-1 pluto[5746]: added connection description "S_I"

    2018:04:16-17:22:49 fw1-1 pluto[5746]: "S_I" #3721: initiating Main Mode

    2018:04:16-17:22:49 fw1-1 pluto[5746]: ERROR: "S_I" #3721: sendto on eth2 to 196.x.y.x5:500 failed in main_outI1. Errno 1: Operation not permitted

    2018:04:16-17:22:59 fw1-1 pluto[5746]: "S_I" #3721: received Vendor ID payload [RFC 3947]

    2018:04:16-17:22:59 fw1-1 pluto[5746]: "S_I" #3721: ignoring Vendor ID payload [FRAGMENTATION c0000000]

    2018:04:16-17:22:59 fw1-1 pluto[5746]: "S_I" #3721: enabling possible NAT-traversal with method 3

    2018:04:16-17:22:59 fw1-1 pluto[5746]: "S_I" #3721: ignoring Vendor ID payload [Cisco-Unity]

    2018:04:16-17:22:59 fw1-1 pluto[5746]: "S_I" #3721: received Vendor ID payload [XAUTH]

    2018:04:16-17:22:59 fw1-1 pluto[5746]: "S_I" #3721: ignoring Vendor ID payload [3da22b408681559536162d208a140ed1]

    2018:04:16-17:22:59 fw1-1 pluto[5746]: "S_I" #3721: ignoring Vendor ID payload [Cisco VPN 3000 Series]

    2018:04:16-17:22:59 fw1-1 pluto[5746]: "S_I" #3721: NAT-Traversal: Result using RFC 3947: no NAT detected

    2018:04:16-17:22:59 fw1-1 pluto[5746]: "S_I" #3721: received Vendor ID payload [Dead Peer Detection]

    2018:04:16-17:22:59 fw1-1 pluto[5746]: | protocol/port in Phase 1 ID Payload is 17/0. accepted with port_floating NAT-T

    2018:04:16-17:22:59 fw1-1 pluto[5746]: "S_I" #3721: Peer ID is ID_IPV4_ADDR: '196.x.y.35'

    2018:04:16-17:22:59 fw1-1 pluto[5746]: "S_I" #3721: Dead Peer Detection (RFC 3706) enabled

    2018:04:16-17:22:59 fw1-1 pluto[5746]: "S_I" #3721: ISAKMP SA established

    2018:04:16-17:22:59 fw1-1 pluto[5746]: "S_I" #3722: initiating Quick Mode PSK+ENCRYPT+TUNNEL+UP {using isakmp#3721}

    2018:04:16-17:23:00 fw1-1 pluto[5746]: "S_I" #3721: ignoring informational payload, type NO_PROPOSAL_CHOSEN

    2018:04:16-17:23:00 fw1-1 pluto[5746]: "S_I" #3721: received Delete SA payload: deleting ISAKMP State #3721

     

    Gery. 

  • In reply to Gery:

    The firewall log line shows that the packet with a source of 91.x.y.13 was dropped out of the OUTPUT chain ("60003").  The IPsec log shows that IPsec is trying to establish from 91.x.y.3.  Please show pictures of the 'Preshared Key Settings' on the 'Advanced' tab, the Edit of the IPsec Connection and the Edit of the Remote Gateway.  Confirm whether the primary Address of the 'Local interface' is 91.x.y.13 or 91.x.y.3.

    Cheers - Bob

  • In reply to BAlfson:

    Hi,

     

    The primary address (Local interface) is 91.x.y.13.

    I attached the pics.

     .

     

    Thank you.

  • In reply to Gery:

    This is confusing, Gery, as the logs don't match.

    First set of logs:

    2018:04:16-12:43:22 fw1-2 pluto[26255]: loaded PSK secret for 91.x.y.3 5.x.y.66
    2018:04:16-12:43:22 fw1-2 pluto[26255]: loaded PSK secret for 91.x.y.3 196.x.y.35
    2018:04:16-12:43:22 fw1-2 pluto[26255]: loaded PSK secret for 91.x.y.3 91.x.y.6

    Second set of logs:

    2018:04:16-17:22:49 fw1-1 pluto[5746]: loaded PSK secret for 91.x.y.13 91.x.y.6
    ...
    2018:04:16-17:22:59 fw1-1 pluto[5746]: "S_I" #3721: Peer ID is ID_IPV4_ADDR: '196.x.y.35'

    Pictures:

    Local Networks = 193.XX.XX.3

    Several questions:

    1. What happens if you try with a simple PSK?
    2. Is either side behind a NAT?
    3. Did you just make a mistake in obfuscating the IP in the first log, or was that the IP at the time?
    4. Is 193.XX.XX.3 a public IP or are you using a public IP internally for this VPN?

    Cheers - Bob

  • In reply to BAlfson:

    maybe they look like they don't match because of me masking things..or details from other VPN tunnels

     

    The peers are these two: loaded PSK secret for 91.x.y.3=local 196.x.y.35=remote

    Local Networks = 193.XX.XX.3  This is correct. Its a Public IP

    On our side we NAT to this public IP (i defined it in interfaces and set it to WAN)

     

    I will try with a simple PSK as well

     

    Thanks.

  • In reply to Gery:

    3. I meant that 91.x.y.3 (first log) <> 91.x.y.13 (second log).

    "On our side we NAT to this public IP (i defined it in interfaces and set it to WAN)"

    I don't understand to which IP that comment applies - please show the Edit of your NAT rule.

    Cheers - Bob 

  • In reply to BAlfson:

    our vpn gateway is 91.x.y.13

    and we NAT to 193.x.y.3

     

    Thanks,

    Gery

  • In reply to Gery:

    Is your NAT rule 'SNAT : {our site's LAN} -> Any -> {other site's LAN} : from IP PUB'?

    You aren't changing the IP that the IPsec messages leave your UTM with are you?

    Cheers - Bob

  • In reply to BAlfson:

    Is your NAT rule 'SNAT : {our site's LAN} -> Any -> {other site's LAN} : from IP PUB'?

    Yes its correct.

    You aren't changing the IP that the IPsec messages leave your UTM with are you?

    I don't quite understand the question.

     

    The thing is i managed to bring this tunnel UP two weeks ago.. but now it wont work whatever i try. (same settings)

    This is from the log when it worked:

    193.x.y.3/32===91.x.y.13[91.x.y.13]:6/445...196.x.y.35[196.x.y.35]:6/0===10.x.Y.0/2x

    In the logs i don't see enough clues..that would point to the problem is on the UTM side or on the ASA side.

     

    Thanks.

    Gery

  • In reply to Gery:

    "You aren't changing the IP that the IPsec messages leave your UTM with are you?

    "I don't quite understand the question"

    One of the reasons an IPsec conversation dies where this one does is a NAT between the two endpoints.  IPsec "signs" that first Main Mode message with the IP of the primary address of the interface.  If the other end sees that the packet arrives from an IP other than the one it was "signed" by, it assumes that the security was broken.  The NAT could be on your end or the other.

    Cheers - Bob