FortiClient - Unable to connect at random times.

[Mitch1973]

Hello,

We're having issues with remote user unable to connect to the VPN at random times, it hangs & they get the messge " VPN connection failed. Please check your configuration, network connection & preshared key". When this happens we check the AD account to ensure its not locked etc & complete basic checks restarting the laptops etc but after while it randomly works without figuring out the root cause. We've tried to replicate but to no avail.

- Upgraded the Forticlient.

- Upgraded FortiOS (6.2.10)

- All config settings match keylifes etc

- PSK is correct.

Looking at the FW logs it seems the client sends a request to tear down the tunnel & doesnt generate phase 2.

 Any help would be greatly appreaciated.

[Mitch1973]

It wont let up add the full log from the FW but this is last part, it it hepls.

ke 7:IPSPEC-MFA_108:142772: dec 779A437980789AD5C36561391365C03E08100601C2AD1B780000008C0C6F31CC0073F97EAEBE91D2944FA28069DB11E40000005001006CCE00010000000200000003000000040000000D00000008000000090000000A0000000B0000000F00007000000070020000700300007006000070010000D40A0000D40B0000000700009785D2E7BED48BA9FDE1A80B

ike 7:IPSPEC-MFA_108:142772: mode-cfg message truncated 112 < 12748, ignoring message

ike 7: comes 82.27.155.30:4500->85.118.8.164:4500,ifindex=75....

ike 7: IKEv1 exchange=Informational id=779a437980789ad5/c36561391365c03e:dc9351ab len=92

ike 7: in 779A437980789AD5C36561391365C03E08100501DC9351AB0000005C1D69AE9A618419C262706F31B5E6C48DE0C60B628D9FEFF6E6F7EA346FAE4D1D2D75B233E11B3269DF385937C4D192B305EBB5DFBE7337AFE8F390A6FB544A98

ike 7:IPSPEC-MFA_108:142772: dec 779A437980789AD5C36561391365C03E08100501DC9351AB0000005C0B0000148D44316EE101C0F61464FAD234D8C902000000200000000101108D28779A437980789AD5C36561391365C03E000007B081D5CCC389C29493E6AAAD0B

ike 7:IPSPEC-MFA_108:142772: notify msg received: R-U-THERE

ike 7:IPSPEC-MFA_108:142772: enc 779A437980789AD5C36561391365C03E08100501E607DA45000000500B000014EB283CEE94900129B1E1112D592FB28D000000200000000101108D29779A437980789AD5C36561391365C03E000007B0

ike 7:IPSPEC-MFA_108:142772: out 779A437980789AD5C36561391365C03E08100501E607DA450000005C185D5DF45983A9A7663E5FA09A30883CAD8286459C7649CF6DBCFAF6802B72EC6A777A1514AA65BC3EA9CF3A043B8A1AD144C06C501C91ABA0AC2A73C46643F4

ike 7:IPSPEC-MFA_108:142772: sent IKE msg (R-U-THERE-ACK): 85.118.8.164:4500->82.27.155.30:4500, len=92, id=779a437980789ad5/c36561391365c03e:e607da45

ike 7: comes 82.27.155.30:4500->85.118.8.164:4500,ifindex=75....

ike 7: IKEv1 exchange=Mode config id=779a437980789ad5/c36561391365c03e:c2ad1b78 len=140

ike 7: in 779A437980789AD5C36561391365C03E08100601C2AD1B780000008C1FF545D6C47AA9C07CD319A5B5E024D79F8E6D055E08AF3504B299408A68ABDA1E25B7A287F67A1214E3C16C3E2E570EAD9C28C6ED32D6583C919FE0414A77987983D56E578923C6DA6F69AC9AA7A3AEAFB4B24B9560B20448D0F7A17C8EF12E4EE8D11D46B4C006C1F96B3EB4B324B9

ike 7:IPSPEC-MFA_108:142772: dec 779A437980789AD5C36561391365C03E08100601C2AD1B780000008C0C6F31CC0073F97EAEBE91D2944FA28069DB11E40000005001006CCE00010000000200000003000000040000000D00000008000000090000000A0000000B0000000F00007000000070020000700300007006000070010000D40A0000D40B0000000700009785D2E7BED48BA9FDE1A80B

ike 7:IPSPEC-MFA_108:142772: mode-cfg message truncated 112 < 12748, ignoring message

ike 7: comes 82.27.155.30:4500->85.118.8.164:4500,ifindex=75....

ike 7: IKEv1 exchange=Informational id=779a437980789ad5/c36561391365c03e:96001b75 len=92

ike 7: in 779A437980789AD5C36561391365C03E0810050196001B750000005C7672A81BE24E6D50A3048AD9E8065A302714C1CDCF73294F515B3CF584D37440EB269681C9755E3E963CEA230791DFFAB44D45BA64C16680C7BAA1282CAE4C7C

ike 7:IPSPEC-MFA_108:142772: dec 779A437980789AD5C36561391365C03E0810050196001B750000005C0C0000146FE3594BBB636964011203B2C9A466B30000001C0000000101100001779A437980789AD5C36561391365C03EB0E3838DA3CEA1ABCDBBBDA7809EE90F

ike 7:IPSPEC-MFA_108:142772: recv ISAKMP SA delete 779a437980789ad5/c36561391365c03e

ike 7:IPSPEC-MFA_108: deleting

ike 7:IPSPEC-MFA_108:142772: HA send IKE SA del 779a437980789ad5/c36561391365c03e

ike 7:IPSPEC-MFA_108: delete dynamic

ike 7:IPSPEC-MFA_108: reset NAT-T

ike 7:IPSPEC-MFA_108: deleted

ike 7: comes 82.27.155.30:4500->85.118.8.164:4500,ifindex=75....

ike 7: IKEv1 exchange=Informational id=779a437980789ad5/c36561391365c03e:96001b75 len=92

ike 7: in 779A437980789AD5C36561391365C03E0810050196001B750000005C7672A81BE24E6D50A3048AD9E8065A302714C1CDCF73294F515B3CF584D37440EB269681C9755E3E963CEA230791DFFAB44D45BA64C16680C7BAA1282CAE4C7C

ike 7: no established IKE SA for exchange-type Informational from 82.27.155.30:4500->85.118.8.164 75 cookie 779a437980789ad5/c36561391365c03e, drop

ike shrank heap by 335872 bytes

[Mitch1973]

This is last part of the client debug log...

1/10/2022 9:35:18 AM Debug VPN with key:
1/10/2022 9:35:18 AM Debug VPN 48e736ba 28fd75c2 abee3e1b aad7bdf6 05bfc81b 2287b822 3fd8ef69 41bd38d9
1/10/2022 9:35:18 AM Debug VPN encrypted payload by IV:
1/10/2022 9:35:18 AM Debug VPN 172a6261 2a437b5e ddce2947 58a89191
1/10/2022 9:35:18 AM Debug VPN save IV for next:
1/10/2022 9:35:18 AM Debug VPN 9526ff88 ae1e8ddf b3894a6a 69e7da64
1/10/2022 9:35:18 AM Debug VPN encrypted.
1/10/2022 9:35:18 AM Debug VPN Adding NON-ESP marker
1/10/2022 9:35:18 AM Debug VPN 92 bytes from 192.168.1.22[4500] to 85.118.8.164[4500]
1/10/2022 9:35:18 AM Debug VPN sockname 192.168.1.22[4500]
1/10/2022 9:35:18 AM Debug VPN send packet from 192.168.1.22[4500]
1/10/2022 9:35:18 AM Debug VPN send packet to 85.118.8.164[4500]
1/10/2022 9:35:18 AM Debug VPN 1 times of 96 bytes message will be sent to 85.118.8.164[4500]
1/10/2022 9:35:18 AM Debug VPN 00000000 b7211803 ff7597bc 95fe92f0 81ec706a 08100501 9457cc8a 0000005c 8884960c 55abfcb3 c793e95e da5b09a3 377689ba 73b7089a 327ef06a 7c135064 73fc8433 152d4776 92918e14 386633b7 9526ff88 ae1e8ddf b3894a6a 69e7da64
1/10/2022 9:35:18 AM Debug VPN sendto Information delete.
1/10/2022 9:35:20 AM Debug Scheduler handle_processtermination() called
1/10/2022 9:35:20 AM Debug Scheduler child process terminates normally
1/10/2022 9:35:20 AM Debug ESNAC dwMiniSecondaryKATout = 20, dwSecondaryKATout = 1800
1/10/2022 9:35:20 AM Debug ESNAC min = 20
1/10/2022 9:35:25 AM Debug ESNAC dwSilentReg false
1/10/2022 9:35:25 AM Debug ESNAC bFirstKA true
1/10/2022 9:35:25 AM Debug ESNAC Start searching for FGT
1/10/2022 9:35:25 AM Debug ESNAC Searching Default GW
1/10/2022 9:35:25 AM Debug ESNAC NetGetDCName failed with error: (0x995)
1/10/2022 9:35:26 AM Debug ESNAC Timeout in select in SocketConnect
1/10/2022 9:35:26 AM Debug ESNAC Socket connect failed
1/10/2022 9:35:26 AM Debug ESNAC 192.168.1.1:8013, Secondary - 0
1/10/2022 9:35:26 AM Debug ESNAC CKeepAlive::SetState
1/10/2022 9:35:26 AM Debug ESNAC Not Registered
1/10/2022 9:35:26 AM Debug ESNAC m_dwAutoconnectWhenOffnet false
1/10/2022 9:35:26 AM Debug ESNAC OnnetOffnet result: false
1/10/2022 9:35:26 AM Debug ESNAC End searching for FGT
1/10/2022 9:35:26 AM Debug ESNAC dwSilentReg false
1/10/2022 9:35:26 AM Debug ESNAC bFirstKA true
1/10/2022 9:35:26 AM Debug ESNAC Start searching for FGT
1/10/2022 9:35:26 AM Debug ESNAC Searching Default GW
1/10/2022 9:35:26 AM Debug ESNAC NetGetDCName failed with error: (0x995)
1/10/2022 9:35:27 AM Debug ESNAC Timeout in select in SocketConnect
1/10/2022 9:35:27 AM Debug ESNAC Socket connect failed
1/10/2022 9:35:27 AM Debug ESNAC 192.168.1.1:8013, Secondary - 0
1/10/2022 9:35:27 AM Debug ESNAC CKeepAlive::SetState
1/10/2022 9:35:27 AM Debug ESNAC Not Registered
1/10/2022 9:35:27 AM Debug ESNAC m_dwAutoconnectWhenOffnet false
1/10/2022 9:35:27 AM Debug ESNAC OnnetOffnet result: false
1/10/2022 9:35:27 AM Debug ESNAC End searching for FGT
1/10/2022 9:35:40 AM Debug ESNAC LD Large data upload command timeout event
1/10/2022 9:35:40 AM Debug ESNAC LD No active EMS connection
1/10/2022 9:35:40 AM Debug ESNAC dwMiniSecondaryKATout = 20, dwSecondaryKATout = 1800
1/10/2022 9:35:40 AM Debug ESNAC min = 20
1/10/2022 9:35:46 AM Debug ESNAC dwSilentReg false
1/10/2022 9:35:46 AM Debug ESNAC bFirstKA true
1/10/2022 9:35:46 AM Debug ESNAC Start searching for FGT
1/10/2022 9:35:46 AM Debug ESNAC Searching Default GW
1/10/2022 9:35:46 AM Debug ESNAC NetGetDCName failed with error: (0x995)
1/10/2022 9:35:47 AM Debug ESNAC Timeout in select in SocketConnect
1/10/2022 9:35:47 AM Debug ESNAC Socket connect failed
1/10/2022 9:35:47 AM Debug ESNAC 192.168.1.1:8013, Secondary - 0
1/10/2022 9:35:47 AM Debug ESNAC CKeepAlive::SetState
1/10/2022 9:35:47 AM Debug ESNAC Not Registered
1/10/2022 9:35:47 AM Debug ESNAC m_dwAutoconnectWhenOffnet false
1/10/2022 9:35:47 AM Debug ESNAC OnnetOffnet result: false
1/10/2022 9:35:47 AM Debug ESNAC End searching for FGT
1/10/2022 9:35:47 AM Debug ESNAC dwSilentReg false
1/10/2022 9:35:47 AM Debug ESNAC bFirstKA true
1/10/2022 9:35:47 AM Debug ESNAC Start searching for FGT
1/10/2022 9:35:47 AM Debug ESNAC Searching Default GW
1/10/2022 9:35:47 AM Debug ESNAC NetGetDCName failed with error: (0x995)
1/10/2022 9:35:48 AM Debug ESNAC Timeout in select in SocketConnect
1/10/2022 9:35:48 AM Debug ESNAC Socket connect failed
1/10/2022 9:35:48 AM Debug ESNAC 192.168.1.1:8013, Secondary - 0
1/10/2022 9:35:48 AM Debug ESNAC CKeepAlive::SetState
1/10/2022 9:35:48 AM Debug ESNAC Not Registered
1/10/2022 9:35:48 AM Debug ESNAC m_dwAutoconnectWhenOffnet false
1/10/2022 9:35:48 AM Debug ESNAC OnnetOffnet result: false
1/10/2022 9:35:48 AM Debug ESNAC End searching for FGT
1/10/2022 9:36:01 AM Debug ESNAC dwMiniSecondaryKATout = 20, dwSecondaryKATout = 1800
1/10/2022 9:36:01 AM Debug ESNAC min = 20
1/10/2022 9:36:07 AM Debug ESNAC dwSilentReg false
1/10/2022 9:36:07 AM Debug ESNAC bFirstKA true
1/10/2022 9:36:07 AM Debug ESNAC Start searching for FGT
1/10/2022 9:36:07 AM Debug ESNAC Searching Default GW
1/10/2022 9:36:07 AM Debug ESNAC NetGetDCName failed with error: (0x995)
1/10/2022 9:36:08 AM Debug ESNAC Timeout in select in SocketConnect
1/10/2022 9:36:08 AM Debug ESNAC Socket connect failed
1/10/2022 9:36:08 AM Debug ESNAC 192.168.1.1:8013, Secondary - 0
1/10/2022 9:36:08 AM Debug ESNAC CKeepAlive::SetState
1/10/2022 9:36:08 AM Debug ESNAC Not Registered
1/10/2022 9:36:08 AM Debug ESNAC m_dwAutoconnectWhenOffnet false
1/10/2022 9:36:08 AM Debug ESNAC OnnetOffnet result: false
1/10/2022 9:36:08 AM Debug ESNAC End searching for FGT
1/10/2022 9:36:08 AM Debug ESNAC dwSilentReg false
1/10/2022 9:36:08 AM Debug ESNAC bFirstKA true
1/10/2022 9:36:08 AM Debug ESNAC Start searching for FGT
1/10/2022 9:36:08 AM Debug ESNAC Searching Default GW
1/10/2022 9:36:08 AM Debug ESNAC NetGetDCName failed with error: (0x995)
1/10/2022 9:36:09 AM Debug ESNAC Timeout in select in SocketConnect
1/10/2022 9:36:09 AM Debug ESNAC Socket connect failed
1/10/2022 9:36:09 AM Debug ESNAC 192.168.1.1:8013, Secondary - 0
1/10/2022 9:36:09 AM Debug ESNAC CKeepAlive::SetState
1/10/2022 9:36:09 AM Debug ESNAC Not Registered
1/10/2022 9:36:09 AM Debug ESNAC m_dwAutoconnectWhenOffnet false
1/10/2022 9:36:09 AM Debug ESNAC OnnetOffnet result: false
1/10/2022 9:36:09 AM Debug ESNAC End searching for FGT