FOS-VM License management, validation, and troubleshooting

[mmaubert]

Description
This article provides some technical tips regarding FortiOS-VM (FOS-VM) Licenses management, validation and troubleshooting.


Solution
FOS-VMs are meant to work only in closed environments without Internet access. FOS-VMs license validation process is exclusively taken care of by the FortiMeter module of FortiManager, not by FortiGuard.

Upon instantiation, a FOS-VM is provided with a permanent Serial Number. The FOS-VM license status is “Valid”, and is set with a “FortiMeter grace period” value of 1 hour.

FOS-VM (global) # get system status
Version: FortiOS-VM64-KVM v5.6.10,build1677,190716 (GA)             <-----FOS-VM
…
Serial-Number: FOSVM1K38A******
…
License Status: Valid
…
FOS-VM (global) # diag hard sysinfo vm full

UUID:    f259d077dcbfa8419c9d480856bf034b
Fortimeter grace period: 3600 seconds                               <-----FortiMeter grace period set to 1 hour

The VM then starts to register to the FortiManager instance that is defined in its configuration file. If the FOS-VM does not or cannot register to a FortiManager instance before the grace period timer elapses, then the license status becomes “Invalid” and the FOS-VM ceases functioning. If it can register, then the “FortiMeter grace period” value is set to 15 days.

Once the FOS-VM is added to FortiManager (promoted), it can then be managed by the FortiMeter module. For the FOS-VM to become fully operational, it has to be authorized by FortiMeter. This can be done by editing the FOS-VM into FortiMeter and authorize it to start processing traffic by assigning a license and possibly UTM services to it.

Typical output of the “get system status” command output once a FOS-VM has been authorized by FortiMeter

FOS-VM (global) # get system status
Version: FortiOS-VM64-KVM v5.6.10,build1677,190716 (GA)
…
Serial-Number: FOSVM1K38A******
…
License Status: Valid
BIOS version : 04000002

Typical output of the “diag hardware sysinfo full” command output once a FOS-VM has been authorized by FortiMeter. The FortiMeter grace period set to 1296000 seconds which corresponds to 15 days.

FOS-VM (global) # diag hardware sysinfo vm full
UUID:     f259d077dcbfa8419c9d480856bf034b
Fortimeter grace period: 1296000 seconds

After it has been authorized by FortiMeter, the FOS-VM tries to contact its FortiManager instance every 5 minutes in order to report metering information. In case FortiManager cannot be contacted, the FOS-VM stores the metering information locally and decrements the FortiMeter grace period value. In the eventuality the FortiMeter grace period goes down to zero, the License Status would then be changed to “Invalid” and the FOS-VM will stop processing traffic. Anyway, such situation does not stop the FOS-VM to continue sending metering data to the FortiManager periodically. In case the communication is re-established at some point in time, the FOS-VM will detect it, set the FortiMeter grace period back to 15 days, and re-start processing traffic again.

Note: the “diag debug vm-print-license” command that can be used with FGT-VM to gather detailed license information is not supported in FOS-VM environment.

Troubleshooting FOS-VM registration or metering issues requires setting the FortiOS “update” daemon in debug mode using the following commands set:

# diag debug application update -1
# diag debug console timestamp enable
# diag debug enable

Note: In all the examples below, and for consistency purpose, the FOS-VM and FortiManager Serial number and IP address are always the same, such as:

- FOS-VM Serial Number is FOSVM1I******-**
- FOS-VM IP address is 10.218.11.**
- FortiManager Serial Number is FMG-VM0A13******
- FortiManager is 10.218.11.**


1) A typical sequence of events corresponding to a registration request (FOS-VM sends a registration request to its configured FortiManager) or de-registration request (FOS-VM is deleted from FortiManager)

Such registration / de-registration requests are detected and recorded with a “Detected override servers change” notification message containing the FortiManager IP address and TCP port. This notification is then systematically followed by a “Starting SETUP” data exchange in between the FOS-VM and the FortiManager (see below).  
  

2019-08-02 11:00:39 upd_centmgmt_change_notif[54]-Detected override servers change
2019-08-02 11:00:39 upd_fds_load_local_list[514]-SEQ  TZ   IP:PORT TYPE
2019-08-02 11:00:39 upd_fds_load_local_list[597]-  1  128  10.218.11.**:8890  4
2019-08-02 11:00:39 upd_fds_load_local_list[605]-================================
2019-08-02 11:00:39 upd_fds_load_local_list[606]-Loaded 1 local servers
2019-08-02 11:00:39 upd_daemon[1215]-Received setup request

2019-08-02 11:00:39 do_setup[235]-Starting SETUP
2019-08-02 11:00:57 upd_act_setup_with_action[191]-Trying FDS 10.218.11.80:8890
2019-08-02 11:00:57 __upd_peer_vfy[305]-Server certificate OK.
2019-08-02 11:00:57 __upd_peer_vfy[305]-Server certificate OK.
2019-08-02 11:00:57 pack_obj[183]-Packing obj=Protocol=3.0|Command=Setup|Firmware=FOSVMK-FW-5.06-1677|SerialNumber=FOSVM1I******-**|Connection=Internet|Address=10.218.11.**:9443|
Language=en-US|TimeZone=2|UpdateMethod=1
2019-08-02 11:00:57 get_fcpr_response[289]-Unpacked obj: Protocol=3.0|Firmware=FMG-VM64-KVM-FW-5.06-1803|SerialNumber=FMG-VM0A13******|Response=202|Persistent=false
2019-08-02 11:00:57 do_setup[285]-SETUP successful

In the “Starting SETUP” messages section, it shows the following sequence of data exchange:

- FOS-VM to FortiManager data are bundled into a “pack_obj[183]“ type message. It includes the protocol version, the command type, the FOS-VM build version, Serial Number, IP address and port, language, timezone, and the update method

- FMG to FOS-VM data are bundled into a “get_fcpr_response[289]” type message. It includes the protocol version, the FortiManager build version, Serial Number and a response code which, when set to 202, indicates that a valid reply

It has to be noted that the “Detected override servers change” and “Starting SETUP” data exchanges do not allow differentiating registration and de-registration requests. In both cases, the set of data exchanged in between the FOS-VM and FortiManager is identical.     
 

3) A typical sequence of events corresponding to the FOS-VM sending Metering information to its configured FortiManager

FOS-VM reports metering information periodically to FortiManager using “Starting METER” notification messages. Those messages contain the number of transmit and receive packets and bytes on a per interface basis. 

2019-08-02 14:46:48 do_meter[537]-Starting METER
2019-08-02 14:46:48 _cache[1198]-   port1 (rx:          0 bytes          0 pkts) (tx:          0 bytes          0 pkts)
2019-08-02 14:46:48 _current[1207]- port1 (rx:     770775 bytes       3433 pkts) (tx:    1683605 bytes       3027 pkts)
2019-08-02 14:46:48 _change[1219]-  port1 (rx:     770775 bytes       3433 pkts) (tx:    1683605 bytes       3027 pkts)
2019-08-02 14:46:48 _cache[1198]-   port2 (rx:          0 bytes          0 pkts) (tx:          0 bytes          0 pkts)
2019-08-02 14:46:48 _current[1207]- port2 (rx:        818 bytes         11 pkts) (tx:       4350 bytes         29 pkts)
2019-08-02 14:46:48 _change[1219]-  port2 (rx:        818 bytes         11 pkts) (tx:       4350 bytes         29 pkts)
2019-08-02 14:46:48 _cache[1198]-   port3 (rx:          0 bytes          0 pkts) (tx:          0 bytes          0 pkts)
2019-08-02 14:46:48 _current[1207]- port3 (rx:        908 bytes         12 pkts) (tx:       4350 bytes         29 pkts)
2019-08-02 14:46:48 _change[1219]-  port3 (rx:        908 bytes         12 pkts) (tx:       4350 bytes         29 pkts)
2019-08-02 14:46:48 _cache[1198]-   port4 (rx:          0 bytes          0 pkts) (tx:          0 bytes          0 pkts)
2019-08-02 14:46:48 _current[1207]- port4 (rx:        908 bytes         12 pkts) (tx:       4350 bytes         29 pkts)
2019-08-02 14:46:48 _change[1219]-  port4 (rx:        908 bytes         12 pkts) (tx:       4350 bytes         29 pkts)
2019-08-02 14:46:48 __make_delta[1235]-   (rx:     773409 bytes       3468 pkts) (tx:    1696655 bytes       3114 pkts)
2019-08-02 14:46:58 pack_obj[183]-Packing obj=Protocol=3.0|Command=Statistics|Firmware=FOSVMK-FW-5.06-1677|SerialNumber=FOSVM1I******-**|Uid=f259d077dcbfa8419c9d480856bf034b|Uptime=940|RAM=2005|CPU=1|
PacketsReceived=0|PacketsSent=3114|BytesReceived=0|BytesSent=1696655
2019-08-02 14:46:58 __upd_act_meter[875]-Trying FMG 10.218.11.**:8890
2019-08-02 14:46:58 __upd_peer_vfy[305]-Server certificate OK.
2019-08-02 14:46:58 __upd_peer_vfy[305]-Server certificate OK.
2019-08-02 14:46:58 get_fcpr_response[289]-Unpacked obj: Protocol=3.0|Firmware=FMG-VM64-KVM-FW-5.06-1803|SerialNumber=FMG-VM0A13******|Response=202|Persistent=false|LicenseType=2
2019-08-02 14:46:58 upd_daemon[1391]-Fortimeter result:0 valid:1                               
2019-08-02 14:46:58 upd_pkg_fortimeter_status[1275]-result:0, valid:1

In the example above, the FOS-VM tries sending a new set of statistics to the Meter module but fails matching the FMG IP address since the FOS-VM has been deleted.
Consequently, after several retries, the FOS-VM update daemon records an error message with a status of ‘result:-1, valid:0’ (cf. upd_daemon[1391]-Fortimeter result:-1 valid:0).

Also, since FMG cannot be accessed, there is no “get_fcpr_response[289]” type message returned from FMG to the FOS-VM this time  


4) A typical sequence of events corresponding to the FOS-VM tries sending Metering information to its configured FortiManager but fails opening a TCP session with it.

2019-08-02 15:32:01 do_meter[537]-Starting METER
2019-08-02 15:32:01 _cache[1198]-   port1 (rx:     914335 bytes       4232 pkts) (tx:    1807554 bytes       3479 pkts)
2019-08-02 15:32:01 _current[1207]- port1 (rx:     919057 bytes       4246 pkts) (tx:    1813736 bytes       3506 pkts)
2019-08-02 15:32:01 _change[1219]-  port1 (rx:       4722 bytes         14 pkts) (tx:       6182 bytes         27 pkts)
2019-08-02 15:32:01 _cache[1198]-   port2 (rx:        958 bytes         13 pkts) (tx:      16500 bytes        110 pkts)
2019-08-02 15:32:01 _current[1207]- port2 (rx:        958 bytes         13 pkts) (tx:      18000 bytes        120 pkts)
2019-08-02 15:32:01 _change[1219]-  port2 (rx:          0 bytes          0 pkts) (tx:       1500 bytes         10 pkts)
2019-08-02 15:32:01 _cache[1198]-   port3 (rx:       1048 bytes         14 pkts) (tx:      16500 bytes        110 pkts)
2019-08-02 15:32:01 _current[1207]- port3 (rx:       1048 bytes         14 pkts) (tx:      18000 bytes        120 pkts)
2019-08-02 15:32:01 _change[1219]-  port3 (rx:          0 bytes          0 pkts) (tx:       1500 bytes         10 pkts)
2019-08-02 15:32:01 _cache[1198]-   port4 (rx:       1048 bytes         14 pkts) (tx:      16500 bytes        110 pkts)
2019-08-02 15:32:01 _current[1207]- port4 (rx:       1048 bytes         14 pkts) (tx:      18000 bytes        120 pkts)
2019-08-02 15:32:01 _change[1219]-  port4 (rx:          0 bytes          0 pkts) (tx:       1500 bytes         10 pkts)
2019-08-02 15:32:01 __make_delta[1235]-   (rx:       4722 bytes         14 pkts) (tx:      10682 bytes         57 pkts)
2019-08-02 15:32:11 pack_obj[183]-Packing obj=Protocol=3.0|Command=Statistics|Firmware=FOSVMK-FW-5.06-1677|SerialNumber=FOSVM1I******-**|Uid=f259d077dcbfa8419c9d480856bf034b|Uptime=302|RAM=2005|CPU=1|
PacketsReceived=0|PacketsSent=57|BytesReceived=0|BytesSent=10682
2019-08-02 15:32:11 __upd_act_meter[875]-Trying FMG 10.218.11.**:8890              
2019-08-02 15:32:11 tcp_connect_fds[240]-Failed connecting after sock writable    <<<   
2019-08-02 15:32:11 upd_comm_connect_fds[435]-Failed TCP connect                  <<<
2019-08-02 15:32:11 __upd_act_meter[878]-Failed connecting to 10.218.11.**:8890   <<<
2019-08-02 15:32:11 upd_daemon[1391]-Fortimeter result:-6 valid:0

In the example above, the FOS-VM tries sending a new set of statistics to the Meter module but fails opening a TCP session with FortiManager.
Consequently, the FOS-VM update daemon records an error message with a status of ‘result:-6, valid:0’ (cf. upd_daemon[1391]-Fortimeter result:-6 valid:0).

Note: There is also no “get_fcpr_response[289]” type message message returned from FMG to the FOS-VM in this case.