GP IPsec tunnel always falling back to SSL

[Ben-Price]

Hi All,

A customer recently migrated for 2 x PA-3020 to 2 x PA-460 running PAN OS 10.1.1. Since migrating they are having some odd issues with Global Protect, 90% of the time GP is connecting as SSL, even though IPsec is enabled on the tunnel, and when occasionally it does connect as IPsec, after 5 mins or some times a couple of hours it will fall back to SSL for a couple of users.

Gateway and portal reside on a loopback interface in the internal zone, and the relevant NAT and security policy rules are allowing ipsec, ike, ssl and panos-globalprotect traffic into the loopback IP address. I am not seeing any significant load on the firewall and on average there are approx. 200 GP clients connecting in.

GPS.log snippet below

T2432) 09/29/21 08:25:55:810 Debug(2494): ----Tunnel creation starts----
(T2432) 09/29/21 08:25:55:810 Debug(2495): Try to create tunnel with gateway gp.globalprotect.com.au
(T2432) 09/29/21 08:25:55:810 Debug(5925): --Set state to Connecting...
(T2432) 09/29/21 08:25:55:811 Debug(2355): proxy , proxyuser , domain globalprotect, user admin, remotehost <Public IP Address>.
(T2432) 09/29/21 08:25:55:811 Debug(6828): use cached deviceSN
(T2432) 09/29/21 08:25:55:822 Debug(2635): Get gateway config.
(T2432) 09/29/21 08:25:55:822 Debug(9910): Need to check gateway cert for gp.globalprotect.com.au
(T2432) 09/29/21 08:25:55:822 Debug(2621): encpostdata, encpostdata=0000027556C4C8D0, encpostdatalen=416
(T2432) 09/29/21 08:25:55:823 Debug(2790): REQID=7,IPADDR=gp.globalprotect.com.au,PORT=443,URL=/ssl-vpn/getconfig.esp,POST=1,PROXY_AUTO=1,PROXY_CFGURL=NULL,PROXY=NULL,PROXY_BYPASS=NULL,PROXY_USER=NULL,PROXY_PASS=****,VERIFY_CERT=0,ADDITIONAL_CHECK=1,SCEP_CERT=,oid=
(T2432) 09/29/21 08:25:55:919 Debug(1299): Send response to client for request https_request
(T2432) 09/29/21 08:25:55:966 Debug(2900): receive pan_msg_ping, 1
(T2432) 09/29/21 08:25:55:967 Debug(2693): gateway gp.globalprotect.com.au's config is
<response status="success">
<need-tunnel>yes</need-tunnel>
<ssl-tunnel-url>/ssl-tunnel-connect.sslvpn</ssl-tunnel-url>
<portal>RemoteVPN_GW_Userlogon-N</portal>
<user>admin</user>
<quarantine>no</quarantine>
<lifetime>2592000</lifetime>
<timeout>10800</timeout>
<disconnect-on-idle>10800</disconnect-on-idle>
<bw-c2s>1000</bw-c2s>
<bw-s2c>1000</bw-s2c>
<gw-address>172.16.0.1</gw-address>
<ipv6-connection>no</ipv6-connection>
<ip-address>10.1.40.90</ip-address>
<netmask>255.255.255.255</netmask>
<ip-address-preferred>yes</ip-address-preferred>
<dns>
<member>10.1.30.200</member>
<member>10.1.30.220</member>
</dns>
<wins>
</wins>
<dns-suffix>
<member>globalprotect.local</member>
</dns-suffix>
<default-gateway>10.1.40.90</default-gateway>
<mtu>0</mtu>
<no-direct-access-to-local-network>no</no-direct-access-to-local-network>
<access-routes>
<member>10.1.6.0/24</member>
<member>10.1.20.0/24</member>
<member>10.1.30.0/24</member>
<member>10.1.33.0/24</member>
<member>10.1.35.0/24</member>
<member>10.1.40.0/23</member>
<member>10.1.43.0/24</member>
<member>10.2.30.0/24</member>
<member>10.2.35.0/24</member>
<member>10.3.10.0/24</member>
<member>10.7.10.0/24</member>
<member>103.96.57.28/32</member>
<member>172.17.14.0/24</member>
<member>172.24.14.0/24</member>
<member>192.168.1.0/24</member>
<member>192.168.2.0/24</member>
<member>192.168.3.0/24</member>
<member>10.12.5.0/24</member>
<member>10.9.5.0/24</member>
<member>10.2.5.0/24</member>
<member>10.1.10.0/23</member>
<member>10.1.4.0/23</member>
<member>10.1.6.0/24</member>
<member>10.1.14.0/23</member>
<member>10.1.30.200/32</member>
<member>10.1.30.220/32</member>
</access-routes>
<exclude-access-routes>
</exclude-access-routes>
<ipsec>
<udp-port>4501</udp-port>
<ipsec-mode>esp-tunnel</ipsec-mode>
<enc-algo>aes-128-cbc</enc-algo>
<hmac-algo>sha1</hmac-algo>
(T2432) 09/29/21 08:25:55:967 Debug(2719): There is no connected-gw-ip
(T2432) 09/29/21 08:25:55:967 Debug(4391): In SetGatewayRoute: The original route table:
(T2432) 09/29/21 08:25:55:967 Debug( 138): Destination NetMask Gateway Inf Metric
(T2432) 09/29/21 08:25:55:967 Debug( 153): 0.0.0.0 0.0.0.0 192.168.15.1 5 25
(T2432) 09/29/21 08:25:55:967 Debug( 153): 127.0.0.0 255.0.0.0 127.0.0.1 1 331
(T2432) 09/29/21 08:25:55:967 Debug( 153): 127.0.0.1 255.255.255.255 127.0.0.1 1 331
(T2432) 09/29/21 08:25:55:967 Debug( 153): 127.255.255.255 255.255.255.255 127.0.0.1 1 331
(T2432) 09/29/21 08:25:55:967 Debug( 153): 192.168.15.0 255.255.255.0 192.168.15.5 5 281
(T2432) 09/29/21 08:25:55:967 Debug( 153): 192.168.15.5 255.255.255.255 192.168.15.5 5 281
(T2432) 09/29/21 08:25:55:967 Debug( 153): 192.168.15.255 255.255.255.255 192.168.15.5 5 281
(T2432) 09/29/21 08:25:55:967 Debug( 153): 224.0.0.0 240.0.0.0 127.0.0.1 1 331
(T2432) 09/29/21 08:25:55:967 Debug( 153): 224.0.0.0 240.0.0.0 192.168.15.5 5 281
(T2432) 09/29/21 08:25:55:967 Debug( 153): 255.255.255.255 255.255.255.255 127.0.0.1 1 331
(T2432) 09/29/21 08:25:55:967 Debug( 153): 255.255.255.255 255.255.255.255 192.168.15.5 5 281
(T2432) 09/29/21 08:25:55:967 Debug(4401): SetGatewayRoute: GetBestRoute() returns Dest:0.0.0.0 Mask:0.0.0.0 if_index=5 metric1=25
(T2432) 09/29/21 08:25:55:967 Debug(4423): Created gateway route (<Public IP Address>) succeeds
(T2432) 09/29/21 08:25:55:968 Debug( 305): gw-address-v6 is not specified
(T2432) 09/29/21 08:25:55:968 Debug( 311): remoteHostV6 is not specified
(T2432) 09/29/21 08:25:55:968 Debug( 336): ip-address-preferred value is yes
(T2432) 09/29/21 08:25:55:968 Debug( 361): ip-address-v6-preferred not found.
(T2432) 09/29/21 08:25:55:968 Debug(9638): Set preferred IP 10.1.40.90 for gateway <Public IP Address> user admin
(T2432) 09/29/21 08:25:55:968 Debug(9647): Set preferred IPv6 for gateway <Public IP Address> user admin
(T15080) 09/29/21 08:25:55:968 Debug(2345): Setting debug level to 5
(T2432) 09/29/21 08:25:55:968 Debug( 501): DLSA, found no-direct-access-to-local-network tag, b_IsDLSASet set to false
(T2432) 09/29/21 08:25:55:968 Debug( 738): Encryption method is aes-128-cbc
(T15080) 09/29/21 08:25:55:968 Debug(2345): Setting debug level to 5
(T2432) 09/29/21 08:25:55:968 Debug(3229): set driver connected as true
(T2432) 09/29/21 08:25:55:968 Debug( 581): use-ssl-only-tunnel is not configured and user cannnot change
(T2432) 09/29/21 08:25:55:968 Debug( 147): VPN idle timeout is 10800; config timeout is 10800
(T2432) 09/29/21 08:25:55:968 Debug( 70): c2s-spi is 0x5734C681, s2c-spi is 0x466EF24D
(T2432) 09/29/21 08:25:55:968 Debug( 189): EnforceDns is enabled, set 2 GP pushed DNS servers
(T2432) 09/29/21 08:25:55:968 Debug( 163): Trying to do ipsec connection to <Public IP Address>[4501]
(T2432) 09/29/21 08:25:55:972 Debug( 550): Network is reachable
(T2432) 09/29/21 08:25:55:973 Info ( 175): Connected to: <Public IP Address>[4501], Sending keep alive to ipsec socket...
(T2432) 09/29/21 08:25:55:980 Warn ( 208): received data not keep alive
(T2432) 09/29/21 08:25:55:980 Warn ( 208): received data not keep alive
(T2432) 09/29/21 08:25:55:980 Warn ( 208): received data not keep alive
(T2432) 09/29/21 08:26:02:006 Info ( 218): failed to receive keep alive
(T2432) 09/29/21 08:26:02:006 Debug( 227): Disconnect udp socket
(T2432) 09/29/21 08:26:02:006 Info ( 319): Connecting to <Public IP Address> failed
(T2432) 09/29/21 08:26:02:006 Info ( 238): Start vpn do_connect() failed
(T2432) 09/29/21 08:26:02:006 Debug( 293): do_disconnect is called in VPN stop
(T2432) 09/29/21 08:26:02:006 Debug( 602): ipsec failed to start
(T2432) 09/29/21 08:26:02:006 Info ( 87): VPN is deleted
(T2432) 09/29/21 08:26:02:006 Debug( 147): VPN idle timeout is 10800; config timeout is 10800
(T2432) 09/29/21 08:26:02:006 Debug( 189): EnforceDns is enabled, set 2 GP pushed DNS servers
(T2432) 09/29/21 08:26:02:006 Debug( 62): Trying to do SSL connection to <Public IP Address>(443)
(T2432) 09/29/21 08:26:02:006 Debug( 777): SSL connecting to <Public IP Address>
(T2432) 09/29/21 08:26:02:021 Debug( 550): Network is reachable
(T2432) 09/29/21 08:26:02:068 Debug(1242): Failed to X509_LOOKUP_load_file
(T2432) 09/29/21 08:26:02:068 Debug( 363): Open_SSL_connection: subject '/OU=Domain Control Validated/CN=*.globalprotect.com.au'
(T2432) 09/29/21 08:26:02:068 Debug( 367): Open_SSL_connection: issuer '/C=US/ST=Arizona/L=Scottsdale/O=GoDaddy.com, Inc./OU=http://certs.godaddy.com/repository//CN=Go Daddy Secure Certificate Authority - G2'
(T2432) 09/29/21 08:26:02:082 Info ( 110): Connected ssl tunnel to <Public IP Address>(443)
(T2432) 09/29/21 08:26:02:082 Info ( 329): tunnel to <Public IP Address> connected
(T2432) 09/29/21 08:26:02:121 Debug( 349): PsvRegister done
(T2432) 09/29/21 08:26:02:121 Debug( 25): create thread 0x67c with thread ID 1036
(T1036) 09/29/21 08:26:02:122 Debug( 398): VpnProcMonitor thread starts
(T1036) 09/29/21 08:26:02:122 Debug( 25): create thread 0x8b4 with thread ID 13636
(T13636) 09/29/21 08:26:02:123 Debug( 409): VpnProcDrv thread starts
(T2432) 09/29/21 08:26:02:129 Error(1606): SaveDnsSuffixRegSettings failed to get registry value UseDomainNameDevolution, error 2
(T2432) 09/29/21 08:26:02:129 Debug(1636): Get original DNS SearchList value globalprotect.local,lan
(T2432) 09/29/21 08:26:02:129 Debug(1657): searchList: globalprotect.local
(T2432) 09/29/21 08:26:02:129 Debug(1657): searchList: lan
(T2432) 09/29/21 08:26:02:148 Debug(1514): domainsuffix, add suffix globalprotect.local
(T2432) 09/29/21 08:26:02:148 Debug(1514): domainsuffix, add suffix lan
(T2432) 09/29/21 08:26:02:148 Debug(1119): Save original dns suffix to registry
(T2432) 09/29/21 08:26:02:148 Debug(1124): Store searchList globalprotect.local
(T15080) 09/29/21 08:26:02:149 Debug(2345): Setting debug level to 5
(T2432) 09/29/21 08:26:02:157 Debug( 983): flush registry successfully
(T2432) 09/29/21 08:26:02:157 Debug(1124): Store searchList lan
(T15080) 09/29/21 08:26:02:158 Debug(2345): Setting debug level to 5
(T2432) 09/29/21 08:26:02:158 Debug( 983): flush registry successfully
(T2432) 09/29/21 08:26:02:158 Debug(1209): domainsuffix, set dns suffix search order
(T2432) 09/29/21 08:26:02:165 Debug(2779): Virtual adapter friendly name is: Ethernet 3
(T2432) 09/29/21 08:26:02:165 Info (3214): Old IPv4 , new IPv4 10.1.40.90.
(T2432) 09/29/21 08:26:02:166 Info (3246): Old subnet mask , new subnet mask 255.255.255.255.
(T2432) 09/29/21 08:26:02:166 Info (3278): Old DNS , new DNS 10.1.30.100,10.1.30.120.
(T2432) 09/29/21 08:26:02:167 Info (3382): ipv4 address changed, DNS address changed.
(T2432) 09/29/21 08:26:02:167 Info (6541): Set IPv4 Address nte_context 0x5a28010a.
(T2432) 09/29/21 08:26:02:168 Debug( 356): SetIpManually takes 0ms.
(T12280) 09/29/21 08:26:02:171 Debug(5491): NetworkConnectionMonitorThread: route change detected. Wait for 3 seconds.
(T2432) 09/29/21 08:26:02:186 Info (3956): SetIpInterfaceEntry(4) success.
(T2432) 09/29/21 08:26:02:186 Debug( 407): Check IP Set takes 0ms.
(T2432) 09/29/21 08:26:02:186 Debug(2175): SetExcludeRoutesV6: there is no route to set
(T2432) 09/29/21 08:26:02:186 Debug( 424): Set IPv6 route takes 0ms.
(T2432) 09/29/21 08:26:02:186 Debug(2100): SetExcludeRoutes: there is no route to set
(T2432) 09/29/21 08:26:02:186 Debug( 436): Set IPv4 route takes 0ms.
(T2432) 09/29/21 08:26:02:187 Debug(3708): Wait for virtual interface IP route entry 10.1.40.90
(T2432) 09/29/21 08:26:05:484 Debug(3720): Found virtual interface IP route entry.
(T2432) 09/29/21 08:26:05:487 Debug(2035): Set access route: ForwardDest = 10.1.6.0, metric 1.
(T2432) 09/29/21 08:26:05:557 Debug(2035): Set access route: ForwardDest = 10.1.10.0, metric 1.
(T2432) 09/29/21 08:26:05:576 Debug(4893): DLSAV6, CPanNetSetup::RemoveDLSARouteV6, cfg=0000027556A93EB0
(T2432) 09/29/21 08:26:05:578 Debug(4918): DLSAV6, our IF index=30, number of defined route is 0, number of routes is 18
(T2432) 09/29/21 08:26:05:578 Debug(4958): DLSAV6, remove previous DLSA success
(T2432) 09/29/21 08:26:05:578 Debug(4974): DLSA, RemoveDLSARoute, cfg=0000027556A93EB0
(T2432) 09/29/21 08:26:05:580 Debug(4995): DLSA, our IF index=30
(T2432) 09/29/21 08:26:05:580 Debug( 25): create thread 0x8a0 with thread ID 14716
(T2432) 09/29/21 08:26:05:580 Debug(2062): Start FlushDNSCache thread 0x8a0
(T2432) 09/29/21 08:26:05:580 Debug( 477): Save route table snapshot...
(T2432) 09/29/21 08:26:05:581 Debug( 655): sslvpn connect(<Public IP Address>) succeed
(T2432) 09/29/21 08:26:05:581 Debug(9602): VPN tunnel is connected.
(T2432) 09/29/21 08:26:05:581 Debug(9606): Enable life time and create life time thread.
(T2432) 09/29/21 08:26:05:581 Debug( 25): create thread 0x8a0 with thread ID 14752

Does anyone have any ideas at what may be the cause here?

Thanks in advnace.

[nikoolayy1]

There seems to be connection issue:

https://knowledgebase.paloaltonetworks.com/KCSArticleDetail?id=kA10g000000ClfoCAC

https://knowledgebase.paloaltonetworks.com/KCSArticleDetail?id=kA14u0000001Uh1CAE&lang=en_US%E2%80%A...

Do you see any Latency issues:

https://docs.paloaltonetworks.com/globalprotect/5-1/globalprotect-app-new-features/new-features-rele...

Also again check if you followed the article corectly:

https://knowledgebase.paloaltonetworks.com/KCSArticleDetail?id=kA10g000000ClKPCA0

You may need to do some captures and flow logs to see if there are increasing counters or if another device is between the palo alto and the client is dropping the traffic:

https://live.paloaltonetworks.com/t5/general-topics/knowledge-sharing-palo-alto-checking-for-drops-r...

[Ben-Price]

Thanks @nikoolayy1, most of that I have already tried.

I do not see any packets in the drop.pcap file when performing a packet capture on the firewall. 

I checked the latency and there does seem to be a lot entries in the GP logs (not sure if that's normal), although from the sample I looked at there was one incident of the pre-tunnel latency being at 394ms and post-tunnel latency being 63ms, those were the highest numbers I saw. Most pre/post tunnel latency number are between 1 - 30ms, so not sure if those numbers would cause this issue?

I know the IPsec tunnel uses ICMP messages as keepalives. From the pcaps I took I can see ICMP messages going from GP client to the GP gateway, but no response from the gateway to client. I would assume that this is a problem, but I took a pcap in my lab on an older version of PAN OS and I see the same thing and the IPsec tunnel works every time there.

Anyhow I have escalated to PAN TAC and they are investigating. Let me know if you have any other thoughts?

[MichaelAshton]

Did you ever hear back from TAC on this? I'm running into the exact same issue on 10.1.3.

[Ben-Price · Accepted solution]

@MichaelAshton In my instance, it has been identified as a bug. PAN engineering is still investigating, no solution as yet.

[nikoolayy1]

You found out that is a bug, nice. About the ICMP reply proably it depends on what stage you are doing the capture maybe you need transmit and receive to be enabled and maybe also Pre-Parse Match as I don't know at what stage is the ICMP for monitoring handled by the firewalls but this is just as an info as I you know what is the issue now. Hope they solve it fast.

[Ben-Price]

@nikoolayy1, Further info on the bug. PAN engineers decrypted the ESP packets and identified a miscellaneous GRE header in the IPsec keepalive packet, so when the client would receive the IPsec keepalive, it would identify it as data and not the keepalive, then fallback to SSL. They said this was caused by a form of memory corruption. PAN found that the issue is triggered, when any one client connected via SSL, this would cause all subsequent connection to be SSL as well. This is why initially after a commit some client would connect via IPsec.

[ShaneTatton]

Any idea if this was fixed in 10.1.4? Or did they give an indication of when it will be added to the bug list?

[MichaelAshton]

It is not fixed in 10.1.4. TAC says it is going to be in the 10.1.5 release.

[Lockstar]

Thank you -  Following this as we have seen the same issue.   I found that clients would initially connect and continue to connect with IPSec so long as their WAN IP did not change. As soon as the wan IP changed, the client falls back to SSL, and all subsequent connections are SSL.   If we pushed a change in client GP config, the sessions will start connecting as IPSec again.

[MichaelAshton]

I can confirm this is similar to the behaviour we experienced. Once you push any new config to the firewall, the clients would connect using IPSec for a short period of time and then all the new clients would fail back to SSL.  They finally made the bug public and updated the known issues in 10.1.X. The bug ID is PAN-181116 and will be fixed in 10.1.5. TAC has confirmed the issue has been patched on their dev 10.1.5 image.

[MichaelAshton]

Hi All,

10.1.4-h4 was just released with the fix for PAN-181116. I am being told that 10.1.5 will be ready at the end of March.

[Michael_Lidgett]

Hi All,

10.1.4-H4 was released this morning and PAN-181116 is listed as a fix.

PAN-181116

Fixed an issue where, after upgrading to a PAN-OS 10.1 release, GlobalProtect tunnels fell back to SSL instead of IPSec due to the inadvertent encapsulation of the ICMP keepalive response from the firewall.

[MichaelAshton]

As I stated above the fix is in 10.1.4-h4 NOT 10.1.4-h2.