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

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

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.

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. 

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

Hi,

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

I attached the pics.

.

Thank you.

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

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.

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 

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 

our vpn gateway is 91.x.y.13

and we NAT to 193.x.y.3

Thanks,

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

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

"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