Technical Note: FortiToken activation failure

[caunon]

Description

This acticle provides some troubleshooting hints to use to troubleshoot problems with FortiToken activation.

Content of the debug log is shown below.

FGT# execute fortitoken activate FTK200140D0xxxxx
Activating FortiToken(s)
19:06:06 fdsm_comm.c[103] __fgfm_connect_ex - Error FGFM connecting errno(0)
19:06:06 fdsm_fsm.c[376] __run - Error SSL connect
Failed.

Activating FortiToken(s)
19:09:08 fdsm_fsm.c[586] fdsm_fsm_task_signal - got task signal
19:09:08 fdsm_fsm.c[220] __run - type=0 state=idle
19:09:08 fdsm_fsm.c[49] __change_state - (idle -> start)
19:09:08 fdsm_task.c[331] fdsm_task_set_status - [2177]new -> received
19:09:08 fdsm_fsm.c[250] __run - processing task (id=2177)
19:09:08 fdsm_fsm.c[49] __change_state - (start -> get-server)
19:09:08 fdsm_svr.c[223] __get_next_fds - got FDS 127.0.0.1:443
19:09:08 fdsm_comm.c[49] __fgfm_create - FGFM create context

19:09:08 fdsm_fsm.c[49] __change_state - (get-server -> tcp-connect)
19:09:08 fdsm_fsm.c[201] __add_timer - added timer (30 sec)
19:09:08 fdsm_fsm.c[508] __handle_poll_event - state=tcp-connect
19:09:08 fdsm_fsm.c[85] __del_timer - cancelled timer
19:09:08 fdsm_fsm.c[220] __run - type=0 state=tcp-connect
19:09:08 fdsm_fsm.c[296] __run - TCP connected to server
19:09:08 fdsm_fsm.c[49] __change_state - (tcp-connect -> ssl-connect)
19:09:08 fdsm_comm.c[95] __fgfm_connect_ex - FGFM connect - want read
19:09:08 fdsm_fsm.c[201] __add_timer - added timer (30 sec)
19:09:08 fdsm_fsm.c[508] __handle_poll_event - state=ssl-connect
19:09:08 fdsm_fsm.c[85] __del_timer - cancelled timer
19:09:08 fdsm_fsm.c[220] __run - type=0 state=ssl-connect
19:09:08 fdsm_comm.c[103] __fgfm_connect_ex - Error FGFM connecting errno(0)
19:09:08 fdsm_fsm.c[376] __run - Error SSL connect
19:09:08 fdsm_task.c[355] fdsm_task_set_timeout - task set timeout

19:09:08 fdsm_fsm.c[163] __reset - FSM RESET
19:09:08 fdsm_task.c[331] fdsm_task_set_status - [2177]received -> error
19:09:08 fdsm_task.c[348] fdsm_task_free - task freed

19:09:08 fdsm_fsm.c[49] __change_state - (ssl-connect -> idle)
Failed.

Scope

FortiToken activation

Solution

The following actions may be used to troubleshoot this issue with the activation of the FortiToken. Firstly, disable the FortiManager settings as listed below:

FGT # conf sys central-management
FGT (central-manage~e) # get
mode : normal
type : fortimanager
schedule-config-restore: enable
schedule-script-restore: enable
allow-push-configuration: disable
allow-pushd-firmware: disable
allow-remote-firmware-upgrade: disable
allow-monitor : disable
serial-number :
fmg : (null)
fmg-source-ip : 0.0.0.0
vdom : root
enc-algorithm : default

It should now be possible to authenticate with the FortiToken.

The succesful update will be seen by running the debug command:

FGT# diag debug app fdsmgmt 255
FGT# diag debug enable
FGT# exe fortitoken activate FTK20014K2Pxxxxx

Activating FortiToken(s)
02:03:49 fdsm_fsm.c[586] fdsm_fsm_task_signal - got task signal
02:03:49 fdsm_fsm.c[220] __run - type=0 state=idle
02:03:49 fdsm_fsm.c[49] __change_state - (idle -> start)
02:03:49 fdsm_task.c[331] fdsm_task_set_status - [47]new -> received
02:03:49 fdsm_fsm.c[250] __run - processing task (id=47)
02:03:49 fdsm_fsm.c[49] __change_state - (start -> get-server)
02:03:49 fdsm_svr.c[223] __get_next_fds - got FDS 216.156.209.22:443
02:03:49 fdsm_comm.c[210] __ssl_create - SSL create context
02:03:49 fdsm_fsm.c[49] __change_state - (get-server -> tcp-connect)
02:03:49 fdsm_fsm.c[201] __add_timer - added timer (30 sec)
02:03:49 fdsm_fsm.c[508] __handle_poll_event - state=tcp-connect
02:03:49 fdsm_fsm.c[85] __del_timer - cancelled timer
02:03:49 fdsm_fsm.c[220] __run - type=0 state=tcp-connect
02:03:49 fdsm_fsm.c[296] __run - TCP connected to server
02:03:49 fdsm_comm.c[293] __ssl_prepare - ready to connect SSL
02:03:49 fdsm_fsm.c[49] __change_state - (tcp-connect -> ssl-connect)
02:03:49 fdsm_comm.c[335] __ssl_connect - SSL connect - want read
02:03:49 fdsm_fsm.c[201] __add_timer - added timer (30 sec)
02:03:50 fdsm_fsm.c[508] __handle_poll_event - state=ssl-connect
02:03:50 fdsm_fsm.c[85] __del_timer - cancelled timer
02:03:50 fdsm_fsm.c[220] __run - type=0 state=ssl-connect
02:03:50 fdsm_comm.c[335] __ssl_connect - SSL connect - want read
02:03:50 fdsm_fsm.c[201] __add_timer - added timer (30 sec)
02:03:50 fdsm_fsm.c[508] __handle_poll_event - state=ssl-connect
02:03:50 fdsm_fsm.c[85] __del_timer - cancelled timer
02:03:50 fdsm_fsm.c[220] __run - type=0 state=ssl-connect
02:03:50 fdsm_comm.c[335] __ssl_connect - SSL connect - want read
02:03:50 fdsm_fsm.c[201] __add_timer - added timer (30 sec)
02:03:50 fdsm_fsm.c[508] __handle_poll_event - state=ssl-connect
02:03:50 fdsm_fsm.c[85] __del_timer - cancelled timer
02:03:50 fdsm_fsm.c[220] __run - type=0 state=ssl-connect
02:03:50 fdsm_comm.c[326] __ssl_connect - SSL connected
02:03:50 fdsm_cmd.c[3893] __ftk_activate_build_request - FCPC for FortiToken Activation is: Protocol=3.2|Command=Update|Firmware=FGT1KB-FW-4.00-482|SerialNumber =FGT1KB390xxxxxxx|TokenItem=FTK200140D0xxxxx
02:03:50 fdsm_cmd.c[217] __build_fcpc_request - built request (len=310)
02:03:50 fdsm_comm.c[482] fdsm_comm_send_request - POST http://216.156.209.22:443/FDSService/token HTTP/1.1

User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1)
Host: 216.156.209.22:443
Cache-Control: no-cache
Connection: close
Content-Type: application/octet-stream
Content-Length: 310

02:03:50 fdsm_comm.c[539] fdsm_comm_send_request - wrote request (len=310)
02:03:50 fdsm_fsm.c[49] __change_state - (ssl-connect -> wait-resp-header)
02:03:50 fdsm_fsm.c[201] __add_timer - added timer (30 sec)
02:03:50 fdsm_fsm.c[508] __handle_poll_event - state=wait-resp-header
02:03:50 fdsm_fsm.c[85] __del_timer - cancelled timer
02:03:50 fdsm_fsm.c[220] __run - type=0 state=wait-resp-header
02:03:50 fdsm_comm.c[580] fdsm_comm_recv_header - read 124 bytes, cnt 124 bytes
02:03:50 fdsm_comm.c[593] fdsm_comm_recv_header - HTTP response code=200
02:03:50 fdsm_comm.c[616] fdsm_comm_recv_header - Got header: resp=200 content=560 bufcnt=0
02:03:50 fdsm_fsm.c[49] __change_state - (wait-resp-header -> wait-resp-data)
02:03:50 fdsm_fsm.c[201] __add_timer - added timer (30 sec)
02:03:50 fdsm_fsm.c[508] __handle_poll_event - state=wait-resp-data
02:03:50 fdsm_fsm.c[85] __del_timer - cancelled timer
02:03:50 fdsm_fsm.c[220] __run - type=0 state=wait-resp-data
02:03:50 fdsm_cmd.c[409] __recv_fcpr_pkg - got rsp header
02:03:50 fdsm_cmd.c[460] __verify_fcpr - FCPR obj: Protocol=3.2|Response=204|Firmware=FPT033-FW-3.21-0766|SerialNumber=FPT-FDS-DELL0007|Server=FDSG|Persistent=f alse|ResponseItem=01000000FTSI00000:200
02:03:50 fdsm_cmd.c[478] __verify_fcpr - invalid FCPR response code: expected 300, received 204
02:03:50 fdsm_cmd.c[1059] __update_parse_response - Parsing object(s) for request 13
02:03:50 fdsm_cmd.c[1067] __update_parse_response - Processing object FTSI...
02:03:50 fdsm_cmd.c[878] __update_process_ftsr - FTK200140D0xxxxx
02:03:50 fdsm_cmd.c[1092] __update_parse_response - Processed obj FTSI (code=200)
02:03:50 fdsm_cmd.c[435] __recv_fcpr_pkg - Processed fcpr
02:03:50 fdsm_task.c[331] fdsm_task_set_status - [47]received -> complete
02:03:50 fdsm_fsm.c[439] __run - Task completed
02:03:50 fdsm_fsm.c[163] __reset - FSM RESET
02:03:50 fdsm_comm.c[195] __reset - COMM RESET
02:03:50 fdsm_comm.c[378] __ssl_close - Closed
02:03:50 fdsm_task.c[348] fdsm_task_free - task freed
02:03:50 fdsm_fsm.c[49] __change_state - (wait-resp-data -> idle)

Done.