|
FortiToken drift indicates a time synchronization issue. It can occur due to a system time change on a FortiGate or a mobile device. For authentication to work correctly, the clocks of the FortiToken and the authentication server must be closely aligned. A similar problem can also appear due to the NTP connectivity issue, as mentioned in this KB article, Technical Tip: SSL VPN user with FortiToken but NTP was not synchronized.
The drift adjustment can be handled by adding a token code from a FortiClient. To verify the issue, run the following debugs and check for the presence of the indicated logs.
diagnose debug reset
diagnose debug console timestamp en
diagnose debug app fnbamd -1
diagnose debug app sslvpn -1
diagnose debug enable
To disable debugs:
diagnose debug disable
diagnose debug reset
If the log 'drifted, asking for the next token' is present, the FortiClient will ask for the Token code again. Wait for the code to change on the mobile device and enter the new code. This will take care of the drift adjustments.
Note: If the same Token code is added twice, it will fail the SSL VPN login with a sync error in the debug logs.
2025-03-29 19:31:41 [962:root:8]user 'amrit' uses 2FA: ctx->peer_two_factor = 0,
ctx->peer_name.peername = 0,
ctx->is_two_factor = 1
2025-03-29 19:31:41 [962:root:0]famStateInit:2249 ctx->token_type = 1, timeout = 60
2025-03-29 19:31:41 [962:root:8][fam_auth_send_req_internal:432] Groups sent to FNBAM:
2025-03-29 19:31:41 [962:root:8]group_desc[0].grpname = 2FA
2025-03-29 19:31:41 [962:root:8][fam_auth_send_req_internal:444] FNBAM opt = 0X200420
2025-03-29 19:31:41 [962:root:8]fam_auth_send_req_internal:505 fnbam_auth_token return: 4
2025-03-29 19:31:41 [2096] handle_req-Rcvd auth_token rsp for req 4131895685121
2025-03-29 19:31:41 [2149] handle_req-Check token '127583' with user 'amrit'
2025-03-29 19:31:41 [2170] handle_req-Verify(user=amrit vdom=root token_code=127583) returns -30118
2025-03-29 19:31:41 [2194] handle_req-Token drifted, asking for the next token
2025-03-29 19:31:41 [239] fnbamd_comm_send_result-Sending result 8 (nid 0) for
req 4131895685121, len=2596
2025-03-29 19:31:41 [962:root:8]fam_auth_proc_resp:1365
fnbam_auth_update_result return: 8 (next token code required)
2025-03-29 19:31:41 [962:root:8]fam_auth_proc_resp:1391
Receive Manually input token result. Push: 0
2025-03-29 19:31:41 [962:root:8][fam_auth_proc_resp:1505]
Authenticated groups (1) by FNBAM with auth_type (1)
:
2025-03-29 19:31:41 [962:root:8]Received: auth_rsp_data.grp_list[0] = 0
2025-03-29 19:31:41 [962:root:8]Auth requires next token
2025-03-29 19:32:09 [963:root:8] two-factor check for amrit: off
2025-03-29 19:32:09 [963:root:8]sslvpn_authenticate_user:203 authenticate user: [amrit]
2025-03-29 19:32:09 [963:root:8]sslvpn_authenticate_user:221 create fam state
2025-03-29 19:32:09 [963:root:8]user 'amrit' uses 2FA:
ctx->peer_two_factor = 0, ctx->peer_name.peername = 0,
ctx->is_two_factor = 1
2025-03-29 19:32:09 [963:root:0]famStateInit:2249 ctx->token_type = 1, timeout = 60
2025-03-29 19:32:09 [963:root:8][fam_auth_send_req_internal:432] Groups sent to FNBAM:
2025-03-29 19:32:09 [963:root:8]group_desc[0].grpname = 2FA
2025-03-29 19:32:09 [963:root:8][fam_auth_send_req_internal:444] FNBAM opt = 0X200420
2025-03-29 19:32:09 [963:root:8]2025-03-29 19:32:09
[2276] handle_req-Rcvd token sync req for 4131895685121
fam_auth_send_req_internal:496 fnbam_auth_token_sync return: 4
2025-03-29 19:32:09 [2288] handle_req-Syncing token '423160' with user 'amrit' '127583'
2025-03-29 19:32:09 [2301] handle_req-Token sync succeeded
2025-03-29 19:32:09 [627]
fnbam_user_auth_group_match-req id: 4131895685121, server: amrit, local auth: 1, dn
match: 0
2025-03-29 19:32:09 [575] __group_match-Group '2FA' passed group matching
2025-03-29 19:32:09 [578] __group_match-Add matched group '2FA'(2)
2025-03-29 19:32:09 [206] find_matched_usr_grps-Passed group matching
2025-03-29 19:32:09 [239] fnbamd_comm_send_result-Sending result 0 (nid 0)
for req 4131895685121, len=2596
2025-03-29 19:32:09 2025-03-29 19:32:09 [600] destroy_auth_session-delete session 4131895685121
[963:root:8]2025-03-29 19:32:09 fam_auth_proc_resp:1365 fnbam_auth_update_result return: 0 (success)
Debug output for IPsec tunnel. When working with an IPsec VPN, a similar kind of error can be seen on the FortiGate, as shown below:
ike V=root:0:IPSECTunnel_7:695127: XAUTH 82880181924320 result FNBAM_NEED_TOKEN
ike V=root:0:IPSECTunnel_7: XAUTH requires token for user "Test"
ike V=root:0:IPSECTunnel_7:695127: sending XAUTH token request
ike 0:IPSECTunnel_7:695127: enc 320E3C5622ECF1F3D8E3A2305950818A0810060125FD8FBF000000630
E00002446D41F40B680F82385BC730AA06E79BC1DA89A3E240B7A384
D17059DB491EACA00000023010090AFC0880002408B0000408C000F466F7
27469546F6B656E20436F6465
ike 0:IPSECTunnel_7:695127: dec 320E3C5622ECF1F3D8E3A2305950818A0810060125FD8FBF
0000005C0E00002431216CEB72EAAC275CCA08F42FCF158B8E97AF7BF455644A571
BF8C4010E81F100000016020090AFC0880002408B0006353136353439B
EC9B59F9905
ike V=root:0:IPSECTunnel_7:695127: received XAUTH_PASSCODE length 6
ike V=root:0:IPSECTunnel_7: XAUTH 82880181924320 pending
ike V=root:0:IPSECTunnel_7:695127: XAUTH 82880181924320 result FNBAM_NEED_NEXT_TOKEN
ike V=root:0:IPSECTunnel_7: XAUTH requires Next token for user "Test"
ike V=root:0:IPSECTunnel_7:695127: sending XAUTH token request
This also indicates the same problem, and can also be fixed either by checking the FortiGate and Client side Time or by performing the below command to sync it.
The sync can also be triggered from the FortiGate:
execute fortitoken sync <FortiToken_ID> <token_code1> <next_token_code2>
Related articles:
Troubleshooting Tip: FortiToken OTP drift adjustment
Technical Tip: FortiToken basic troubleshooting
|
