Technical Tip: Unable to see local ID in some of IPsec VPN logs

anoushiravan · ‎04-15-2024

Description

This article describes that the LocalID setting in phase1 of the IPsec tunnel is used on the hub side to identify the incoming IKE connection coming from which spoke IP on the same WAN interface.

Scope

FortiGate

Solution

The local ID is negotiated in phase1 but since the local ID is received in a third packet of main mode when using IKEv1 OR in a second packet of AUTH packet when using IKEv2, therefore the local ID in some of the IPsec VPN logs to the initial IKE negotiation (IKE negotiation with same cookie ID) will be N/A in the field of user on IPsec VPN logs.

Note:

The third packet of IKEv1 and a second packet of AUTH packet of IKEv2 are always received via port 4500 when NAT traversal is forced or IKE port is changed from 500 to 4500, here are ike negotiation in IKEv1 and IKEv2 that local ID is negotiated:

IKEv1:

---------------
2024-04-15 13:26:51.200751 ike V=root:0:hub1:74244: sent IKE msg (ident_r2send): 10.109.16.189:500->10.109.16.73:500, len=380, vrf=0, id=aec049302e95a2df/3cc362fb6c53f249 <<--------
2024-04-15 13:26:51.200994 ike 0:hub1:74244: ISAKMP SA aec049302e95a2df/3cc362fb6c53f249 key 16:457A463E9A5C2A3CE30845452495F493
2024-04-15 13:26:51.204014 ike V=root:0: comes 10.109.16.73:4500->10.109.16.189:4500,ifindex=7,vrf=0,len=144.... <<---- due to NAT traversal, 3th message is received with port 4500
2024-04-15 13:26:51.204129 ike V=root:0: IKEv1 exchange=Identity Protection id=aec049302e95a2df/3cc362fb6c53f249 len=140 vrf=0
2024-04-15 13:26:51.204190 ike 0: in AEC049302E95A2DF3CC362FB6C53F24905100201000000000000008C8DFEF4F052A05F1481B80F658BDE698057CACC43EE95A4822F4C37082FEF97F9941ED536A5313E073468F449A76209FEC204AD0850485EDC5A0017EFC1B5AD2AA0F14EA699A5374B6C6F75AFCADF0DA966CBF188E19AA2A3C00021DA2943621B446F7209433A6DC610F45E6EA06EBAD9
2024-04-15 13:26:51.204286 ike V=root:0:hub1: HA state master(2)
2024-04-15 13:26:51.204344 ike V=root:0:hub1:74244: responder: main mode get 3rd message... <<--------
2024-04-15 13:26:51.204465 ike 0:hub1:74244: dec AEC049302E95A2DF3CC362FB6C53F24905100201000000000000008C0800000E0200000073706F6B65310B000024A7DD40C31390A05114626F8D800D6CE1AAB9C90BFF3E98EBA733541D017FA36C0B00001C0000000101106002AEC049302E95A2DF3CC362FB6C53F249000000200000000101107DF9AEC049302E95A2DF3CC362FB6C53F2490A0A0A023D01
2024-04-15 13:26:51.204555 ike V=root:0:hub1:74244: received p1 notify type INITIAL-CONTACT
2024-04-15 13:26:51.204611 ike V=root:0:hub1:74244: received p1 notify type INTERFACE-ADDR4
2024-04-15 13:26:51.204667 ike V=root:0:hub1:74244: INTERFACE-ADDR4 10.10.10.2
2024-04-15 13:26:51.204722 ike V=root:0:hub1:74244: received peer identifier FQDN 'spoke1' <<-------- received local ID 'spoke1' from spoke side
2024-04-15 13:26:51.204845 ike V=root:0:hub1:74244: PSK authentication succeeded

IKEv2:

---------------
2024-04-15 13:03:34.394332 ike V=root:0:hub1:74006: sent IKE msg (SA_INIT_RESPONSE): 10.109.16.189:500->10.109.16.73:500, len=432, vrf=0, id=114d19e3a980e042/87507b67ce15b3bb, oif=7
2024-04-15 13:03:34.394679 ike 0:hub1:74006: IKE SA 114d19e3a980e042/87507b67ce15b3bb SK_ei 16:5334A4AC1725FB0A2C46F13893B330F4
2024-04-15 13:03:34.394780 ike 0:hub1:74006: IKE SA 114d19e3a980e042/87507b67ce15b3bb SK_er 16:6DCB818443B965624D1841BE8047A8C7
2024-04-15 13:03:34.394870 ike 0:hub1:74006: IKE SA 114d19e3a980e042/87507b67ce15b3bb SK_ai 32:F129997A6369753FE922AE1A7AB6B87FF96AB162E11BC13604A98C278BFDD059
2024-04-15 13:03:34.394951 ike 0:hub1:74006: IKE SA 114d19e3a980e042/87507b67ce15b3bb SK_ar 32:F955E16B9A7148286CDCBB3538544B38632932B8AE6F22E79C105D555D845799
2024-04-15 13:03:34.405633 ike V=root:0: comes 10.109.16.73:4500->10.109.16.189:4500,ifindex=7,vrf=0,len=244.... <<---- due to NAT traversal, AUTH message is received with port 4500
2024-04-15 13:03:34.405802 ike V=root:0: IKEv2 exchange=AUTH id=114d19e3a980e042/87507b67ce15b3bb:00000001 len=240
2024-04-15 13:03:34.405877 ike 0: in 114D19E3A980E04287507B67CE15B3BB2E20230800000001000000F0230000D4BB83DBEE9E40ABAA21569225720AE75E2B4D2FFDC2137AA31707CDFAC80B150EF5E76D48B8653E064D9E4AAB3928D53F01E70AAC206749DA298A93415FBA5E0C83FEE700A0DAFEDFD6AD81017837E610A7174A710D7581ED7FCCE3B33529231AD8641AC8E1873442D13075E5099EF2255E30590573F91FF3B3A3C6F04715EA377A1FA400B0EBD12A0C0E680B873AAFCF5F9211E1C7B7A8C8370165ACEEBA74CC16AD7202BB7A14974CFB950E9FC04D68FA64C6B7211D14C25AC5F04F29076E600322E73DAB22C0B47FC8F8CDDD083BA2
2024-04-15 13:03:34.406009 ike V=root:0:hub1: HA state master(2)
2024-04-15 13:03:34.406221 ike 0:hub1:74006: dec 114D19E3A980E04287507B67CE15B3BB2E20230800000001000000CE230000042900000E0200000073706F6B653129000008000040002700000C0000F0F90A0A0A022900002802000000BA322CFFEFE3FEE0BA1A19689345C4E7C3AE50C869A9F1F63694352C0F59E81E21000008000040242C00002C0000002801030403C8B8C91F0300000C0100000C800E0080030000080300000200000008050000002D00001801000000070000100000FFFF00000000FFFFFFFF0000001801000000070000100000FFFF00000000FFFFFFFF
2024-04-15 13:03:34.406344 ike V=root:0:hub1:74006: responder received AUTH msg
2024-04-15 13:03:34.406344 ike V=root:0:hub1:74006: responder received AUTH msg <<<---------
2024-04-15 13:03:34.406419 ike V=root:0:hub1:74006: processing notify type INITIAL_CONTACT
2024-04-15 13:03:34.406761 ike V=root:0:hub1:74006: processing notify type INTERFACE_ADDR4
2024-04-15 13:03:34.407091 ike V=root:0:hub1:74006: INTERFACE-ADDR4 10.10.10.2
2024-04-15 13:03:34.407175 ike V=root:0:hub1:74006: processing notify type MESSAGE_ID_SYNC_SUPPORTED
2024-04-15 13:03:34.407394 ike V=root:0:hub1:74006: received peer identifier FQDN 'spoke1' <<<---------
2024-04-15 13:03:34.407476 ike V=root:0:hub1:74006: re-validate gw ID
2024-04-15 13:03:34.407564 ike V=root:0:hub1:74006: gw validation OK

Here are some IPsec VPN logs for IKEv2, where the local ID appears in field of the user after the local ID is negotiated:

date=2024-04-15 time=13:03:35 eventtime=1713179014406578289 tz="+0200" logid="0101037120" type="event" subtype="vpn" level="notice" vd="root" logdesc="Negotiate IPsec phase 1" msg="negotiate IPsec phase 1"
action="negotiate" remip=10.109.16.73 locip=10.109.16.189 remport=500 locport=4500 outintf="wan1" srccountry="Reserved" cookies="114d19e3a980e042/87507b67ce15b3bb" user="N/A"<-----
group="N/A" useralt="N/A" xauthuser="N/A" xauthgroup="N/A" assignip=N/A vpntunnel="hub1" status="success" result="N/A" peer_notif="CONNECTED" <<<---------
fctuid="N/A" advpnsc=0

date=2024-04-15 time=13:03:35 eventtime=1713179014408033555 tz="+0200" logid="0101037127" type="event" subtype="vpn" level="notice" vd="root" logdesc="Progress IPsec phase 1" msg="progress IPsec phase 1"
action="negotiate" remip=10.109.16.73 locip=10.109.16.189 remport=500 locport=4500 outintf="wan1" srccountry="Reserved" cookies="114d19e3a980e042/87507b67ce15b3bb" user="spoke1" <-----
group="N/A" useralt="N/A" xauthuser="N/A" xauthgroup="N/A" assignip=N/A vpntunnel="hub1" status="success" init="remote" exch="AUTH" dir="inbound" role="responder" result="OK" version="IKEv2" fctuid="N/A" advpnsc=0

Related articles:
Technical Tip: How to use local-ID type IP address other than the IP addresses configured in the int...

Technical Tip: Use of PeerID and LocalID in IPsec VPN between two FortiGates