3.4K
Every now and then we all run into situation where software is not behaving as intended leaving us with the most battle tested troubleshooting approach ever discovered. Rebooting the whole system, crossing fingers and hoping that whatever went wrong inside the blackbox starts up again correctly and automagically recovers from its failed state. Does it work? Yes – sometimes just rebooting a system resolves issues at hand but most of the times a more graceful approach might be the better choice before resorting to a complete system halt. In this post we will look at managing Firepower processes with pmtool, a convinient command-line utility for interacting with Firepowers process manager.
Table Of Contents
Meet Firepower Process Manager
Process Manager (pm) is responsible for managing and monitoring all Firepower related processes on your system. It takes care of starting up all components on startup and restart failed processes during runtime. To interact with Process Manager the CLI utiltiy pmtool is available. Pmtool can be used to disable, enable, (re-)start services or just check the status of the various services PM is managing.
Which processes can I manage with pmtool?
Before diving into where we find pmtool and the specific syntax of managing the different firepower components let’s take a look at some important processes on both FMC and FTD
Firepower Management Center
| Process | Description |
|---|---|
| adi | User Identity integration. ADI polls Active Directory for user:group mappings and integrates into ISE using pxGRID to download and parse session information (which are then handed over to SFDataCorrelator). Additionally adi is responsible for sending remediation requests to ISE |
| sftunnel | Encrypted communication tunnel between FMC and FTD. Used to push configuration and exchange state information between FMC and FTD |
| SFDataCorrelator | Processes various (event) data streams and correlates received data with other datasets. SFDC stitches together sensor events with vulnerability data available on FMC to enrich events but also processes things like user identity mappings and a lot of data correlation related tasks. |
| diskmanager | Cleanup of old files like url databases, user identity dumps and various cache files |
| sla | Smart Licensing agent |
| CloudAgent | Reaches out to AMP and Talos Cloud for ClamAV, URL Filtering and Security Intelligence updates |
| ui_archiver | Monitors the mysql database that the (depcrecated) user agent inserts user:ip mappings into and creates ui.bin files that are then processed by SFDataCorrelator |
| SSEConnector | Agent that connects to Security Services Exchange for registering devices to SSE and shipping security events to the Cloud |
| Prometheus | Backend for the new Health monitoring dashboard introduced with Firepower 6.7.0 |
| tid | Threat Intelligence Director backend |
| mysqld | The old mysql database backend (which is being replaced by sybase) |
| vmsDbEngine | The new database backend which slowly but steadily replaces the old mysql database backend |
| syncd | FMC High Availability synchronisation |
| Tomcat | Java Webserver that hosts FMC REST API and is required by the UI to work |
Firepower Threat Defense
| Process | Description |
|---|---|
| adi | User identity integration. Directly connects to directory servers defined in realm configuration for authenticating captive portal users |
| sftunnel | Encrypted communication tunnel between FMC and FTD. Used to push configuration and exchange state information between FMC and FTD |
| EventHandler | Processes UnifiedEvents (Connection/AMP/IPS Events) generated by snort |
| SFDataCorrelator | Processes various (event) data streams and correlates received data with other datasets. SFDC stitches together sensor events with vulnerability data available on FMC to enrich events but also processes things like user identity mappings and a lot of data correlation related tasks. |
| DetectionEngine | Snort Detection Engine (NGFW portion of FTD) handling TLS Decryption, AVC, IPS, AMP, URL Filtering, Security Intelligence, etc. As for Firepower 6.7.0 (managed by FMC) Snort2 is being used which will be replaced with Snort3 soon |
| ngfwManager | Handles configuration deployment to lina and manages High Availability on FTD devices (responsible for synchronising data between peers) |
| lina | Stateful inspection engine. Lina stands for Linux over ASA and represents the good ol’ ASA code that still lives on in Firepower Threat Defense. Do not touch this process or FTD will reboot! |
| diskmanager | Cleanup of old files like url databases, user identity dumps and various cache files |
| mysqld | Mysql database backend |
| tomcat | Java Webserver that hosts Firepower Device Manager |
| bltd | Process that handles traffic destined to captive portal (exposes a UNIX socket which is used by snort to redirect traffic to bltd which in turn translates the source ip to 169.254.x.x and forwards the traffic to idhttpsd) |
| idhttpsd | Webserver hosting captive portal |
Now that we are aware of the different important processes running behind the scenes let’s take a look where pmtool is located and how we can use it to troubleshoot communication problems between FMC and FTD.
Where do I find pmtool?
On FTD pmtool is available from SFCLI (>) while on FMC you will need a bash root shell (root@ftd01:~#)
to access pmtool.
Before executing pmtool on FMC we will need to access the bash shell and change users to root. This can be done by executing the expert command from SFCLI followed by sudo -i
> expert
admin@ftd01:~$ sudo -i
Password:
root@ftd01:~#What commands does pmtool provide?
While there a lot of different commands that might be handy for very specific troubleshooting scenario we will focusing on the following:
root@ftd01:/home/admin# pmtool --help RestartByID
RestartByType
DisableByID
EnableByID
DisableByType
EnableByType
StatusDisplaying process status
To get a quick overview of the running processes we can execute the status command and grep the important information
root@ftd01:/home/admin# pmtool status | grep " - " loggerd (system) - Running 4519
SFDataCorrelator (normal) - Running 4871
expire-session (normal) - Running 4872
TSS_Daemon (normal) - Running 4873
snapshot_manager (normal) - Running 4874
mysqld (system,gui,mysql) - Running 4520
httpsd (system,gui) - Waiting
idhttpsd (system,gui) - Running 17335
sfmb (normal) - Running 4539
sftunnel (system) - Running 12858
sfmgr (system) - Running 12859
sfmbservice (normal) - Running 12860
fpcollect (normal) - Running 4863
ntpd (normal) - Running 6335
Syncd (normal) - Running 4864
Pruner (normal) - Running 4865
ReconcileState (system) - Running 4545
ActionQueueScrape (system) - Running 4866
rotate_stats (normal) - Running 4867
run_hm (normal) - Running 8935
sfestreamer (normal) - Waiting
sfipproxy (normal) - Running 12861
sftop (normal) - Running 4548
detectionhealthd (normal) - Running 4549
rrd_server (normal) - Running 4550
snmpd (normal) - Waiting
sfhassd (normal) - Running 4551
diskmanager (normal) - Running 15189
adi (normal) - Running 7708
bltd (normal) - Running 4554
pdts_proc (system) - Running 4555
ndmain (normal) - Running 4556
ndclientd (normal) - Running 4557
logmonitor (normal) - Running 4558
ngfwManager (normal) - Running 4989
ASAConfig (normal) - Running 4990
tomcat (normal) - Waiting
CloudAgent (system) - Waiting
beakerd (system) - Waiting
stunnel (normal) - Running 4559
UEChanneld (normal) - Waiting
SSEConnector (system) - Running 12880
rsyncd (normal) - Running 4992
dhcpd (normal) - Waiting
EventHandler (normal) - Running 4868
hmdaemon (normal) - Running 8917
lina (system) - Running 4560
srt (system) - Waiting
systemCGroup (normal) - Running 4563
b2b3f6aa-3dfb-11ea-be9c-2066de410c5c-d01 (de,snort) - Running 11536
b2b3f6aa-3dfb-11ea-be9c-2066de410c5c-d02 (de,snort) - Running 11537
b2b3f6aa-3dfb-11ea-be9c-2066de410c5c-d03 (de,snort) - Running 11538
773010ea-3df2-11ea-b8af-7f5efeab3d9e-ep (ep) - Running 17685
RUAScheduledDownload - Period 3600 - Next run Sun May 2 11:00:00 2021
OptimizeTablesDaily - Period 86400 - Next run Mon May 3 05:00:00 2021
OptimizeTablesWeekly - Period 604800 - Next run Sun May 9 05:30:00 2021 When looking over the list of processes you might see some of them in the Waiting state. Processes in waiting state might not be required in your current setup (e.g. tomcat might not be running if your device is managed by FMC, since it is only required by FDM)
Ok – so we got a list of all the processes, let’s dig a bit deeper and check out the sftunnel process
root@ftd01:/home/admin# pmtool status | grep sftunnel sftunnel (system) - Running 12858
Command: /ngfw/usr/local/sf/bin/sftunnel -d -f /etc/sf/sftunnel.conf
PID File: /ngfw/var/sf/run/sftunnel.pid
Enable File: /ngfw/etc/sf/sftunnel.conf
Command: /ngfw/usr/local/sf/bin/sfmgr -d -f /etc/sf/sftunnel.conf
Enable File: /ngfw/etc/sf/sftunnel.conf
Requires: sftunnel
Command: /ngfw/usr/local/sf/bin/sfmbservice -d -f /etc/sf/sftunnel.conf
Enable File: /ngfw/etc/sf/sftunnel.conf
Requires: sfmb,sftunnel
Requires: sftunnel Looks like sftunnel is up and running. The process was initiated using the command /ngfw/usr/local/sf/bin/sftunnel -d -f /etc/sf/sftunnel.conf and has a process ID (PID) of 12858
To verify the information obtained through pmtool we can use ps (process status) which ships with most Linux distributions
root@ftd01:/home/admin# ps ax | grep 12858
12858 ? Sl 49:58 /ngfw/usr/local/sf/bin/sftunnel -d -f /etc/sf/sftunnel.confGreat – now that we know how to verify process status using pmtool let’s go ahead and try restarting sftunnel
Note
Restarting sftunnel is a safe operation that can be performed without a maintenance window. The communication channel between FMC and FTD is briefly interruptedbut gets re-established in a few seconds after starting up the process
Tip
Always restart sftunnel from the sensor and not from FMC if you are having problem with a single device, otherwise all sftunnel connections to your sensor will need to be re-established
Restarting processes
root@ftd01:/home/admin# pmtool restartbyid sftunnelIt will take a few seconds to restart a process, just wait a bit and your shell should greet you again with a prompt.
To verify that the process has been restarted successfully we will check the status once more and verify that the PID has indeed changed
root@ftd01:/home/admin# pmtool status | grep sftunnel
sftunnel (system) - Running 1944
Command: /ngfw/usr/local/sf/bin/sftunnel -d -f /etc/sf/sftunnel.conf
PID File: /ngfw/var/sf/run/sftunnel.pid
Enable File: /ngfw/etc/sf/sftunnel.conf
Command: /ngfw/usr/local/sf/bin/sfmgr -d -f /etc/sf/sftunnel.conf
Enable File: /ngfw/etc/sf/sftunnel.conf
Requires: sftunnel
Command: /ngfw/usr/local/sf/bin/sfmbservice -d -f /etc/sf/sftunnel.conf
Enable File: /ngfw/etc/sf/sftunnel.conf
Requires: sfmb,sftunnel
Requires: sftunnel If you are interested in to what is happening behind the scene go ahead and tail the messages logfile for any sftunnel related entries:
sftunnel log output
tail -f /ngfw/var/log/messages | grep -i sftunnel May 2 11:17:27 ftd01 SF-IMS[4515]: [4515] pm:control [INFO] Control connection accepted from sudo_user 'admin', cmd 'pmtool restartbyid sftunnel', pid 1925 (uid 0, gid 0)
May 2 11:17:27 ftd01 SF-IMS[4515]: [4515] pm:control [INFO] ControlHandler auditing message->type 0x9000, from 'admin', cmd 'pmtool restartbyid sftunnel', pid 1925 (uid 0, gid 0)
May 2 11:17:27 ftd01 SF-IMS[4515]: [4515] pm:process [INFO] Locking sftunnel
May 2 11:17:27 ftd01 SF-IMS[4515]: [4515] pm:process [INFO] Stopping sftunnel's dependent sfmgr
May 2 11:17:27 ftd01 SF-IMS[4515]: [4515] pm:process [INFO] Stopping sftunnel's dependent sfmbservice
May 2 11:17:27 ftd01 SF-IMS[4515]: [4515] pm:process [INFO] Stopping sftunnel's dependent sfipproxy
May 2 11:17:27 ftd01 SF-IMS[12858]: [12872] sftunneld:sf_connections [INFO] DISCONNECTED:do_services_read_write: Broken connection to service 8400 (FD 12), peer fmc.example.com
May 2 11:17:27 ftd01 SF-IMS[12858]: [12872] sftunneld:sf_peers [INFO] Confirm RPC service in CONTROL channel
May 2 11:17:27 ftd01 SF-IMS[12859]: [12972] sfmgr:sfmanager [INFO] WRITE_THREAD:Terminated sftunnel write thread for peer fmc.example.com
May 2 11:17:27 ftd01 SF-IMS[12858]: [12872] sftunneld:sf_connections [INFO] DISCONNECTED:do_services_read_write: Broken connection to service 6666 (FD 15), peer fmc.example.com
May 2 11:17:29 ftd01 SF-IMS[12858]: [12872] sftunneld:sf_connections [INFO] DISCONNECTED:do_services_read_write: Broken connection to service 8306 (FD 67), peer fmc.example.com
May 2 11:17:33 ftd01 SF-IMS[12858]: [12858] sftunneld:control_services [ERROR] Received signal SF_SIG_TERM or SF_SIG_ALLOC_FAILED
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:sf_connections [WARN] Exit peer fmc.example.com - stopping sftunnel
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:sf_connections [INFO] Received SIGTERM...Shutting down the sftunnel for fmc.example.com
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:sf_connections [INFO] <<<<<<<<<<<<<<<<<<<<<< ShutDownPeer fmc.example.com >>>>>>>>>>>>>>>>>>>>>>>>
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:TunnelService [INFO] UEC service 9101 is signaled to exit for peer fmc.example.com
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:TunnelService [INFO] UEC service 9100 is signaled to exit for peer fmc.example.com
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:TunnelService [WARN] UEC service 9101 exited for peer fmc.example.com
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:TunnelService [WARN] UEC service 9100 exited for peer fmc.example.com
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:stream_file [INFO] Stream CTX destroyed for fmc.example.com
May 2 11:17:33 ftd01 SF-IMS[4871]: [5372] SFDataCorrelator:EventStreamHandler [ERROR] SFTunnelReadBuffer returned 26: Closed
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:sf_channel [INFO] >> ChannelState ShutDownPeer peer fmc.example.com / channelA / CONTROL [ msgSock & ssl_context ] <<
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:sf_channel [INFO] >> ChannelState freeChannel peer fmc.example.com / channelA / DROPPED [ msgSock & ssl_context ] <<
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:sf_channel [INFO] >> ChannelState ShutDownPeer peer fmc.example.com / channelB / EVENT [ msgSock2 & ssl_context2 ] <<
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:sf_channel [INFO] >> ChannelState freeChannel peer fmc.example.com / channelB / DROPPED [ msgSock2 & ssl_context2 ] <<
May 2 11:17:33 ftd01 SF-IMS[4871]: [5392] SFDataCorrelator:DM_peercomms [ERROR] Failed to read from SFTunnel, error 20: General read error
May 2 11:17:33 ftd01 SF-IMS[4871]: [5392] SFDataCorrelator:DM_peercomms [ERROR] Failed to read from SFTunnel, error 24: Not connected
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:sf_connections [INFO] Peer fmc.example.com is not configured...Exiting
May 2 11:17:33 ftd01 SF-IMS[4871]: [5369] SFDataCorrelator:DM_peercomms [ERROR] Failed to read from SFTunnel, error 20: General read error
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:sf_peers [INFO] Free peer fmc.example.com
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:sf_channel [INFO] >> ChannelState free_peer peer fmc.example.com / channelA / NONE [ msgSock & ssl_context ] <<
May 2 11:17:33 ftd01 SF-IMS[4871]: [5369] SFDataCorrelator:DM_peercomms [ERROR] Failed to read from SFTunnel, error 24: Not connected
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:sf_channel [INFO] >> ChannelState free_peer peer fmc.example.com / channelB / NONE [ msgSock & ssl_context ] <<
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:stream_file [INFO] Stream CTX destroyed for fmc.example.com
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:sf_peers [INFO] Free peer fmc.example.com on exit
May 2 11:17:33 ftd01 SF-IMS[4871]: [5365] SFDataCorrelator:DM_peercomms [ERROR] Failed to read from SFTunnel, error 20: General read error
May 2 11:17:33 ftd01 SF-IMS[4871]: [5365] SFDataCorrelator:DM_peercomms [ERROR] Failed to read from SFTunnel, error 24: Not connected
May 2 11:17:33 ftd01 SF-IMS[12858]: [12872] sftunneld:stream_file [INFO] Stream CTX destroyed for fmc.example.com
May 2 11:17:35 ftd01 SF-IMS[12858]: [12858] sftunneld:sftunnel [INFO] Shutting down after threads exited
May 2 11:17:35 ftd01 SF-IMS[12858]: [12858] sftunneld:sftunnel [INFO] SFTUNNEL is exiting...exit code is: 0
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Event queue priority: [0]
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Insertion rate: 0.00
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Dequeue rate: 0.00
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Average size: 0.00
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Total inserted: 0
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Total dropped: 0
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO]
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Event queue priority: [1]
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Insertion rate: 0.00
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Dequeue rate: 0.00
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Average size: 0.00
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Total inserted: 0
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Total dropped: 0
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO]
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Event queue priority: [2]
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Insertion rate: 0.00
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Dequeue rate: 0.00
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Average size: 0.00
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Total inserted: 0
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Total dropped: 0
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO]
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Event queue priority: [1]
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Insertion rate: 0.00
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Dequeue rate: 0.00
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Average size: 0.00
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Total inserted: 0
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Total dropped: 0
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO]
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Event queue priority: [2]
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Insertion rate: 0.00
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Dequeue rate: 0.00
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Average size: 0.00
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Total inserted: 0
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO] Total dropped: 0
May 2 11:17:36 ftd01 SF-IMS[12858]: [12858] sftunneld:DataMessaging_EventQueue [INFO]
May 2 11:17:36 ftd01 SF-IMS[4515]: [4515] pm:process [INFO] Process sftunnel (12858) stopped.
May 2 11:17:36 ftd01 SF-IMS[4515]: [4515] pm:log [INFO] Process 'sftunnel' closed output.
May 2 11:17:36 ftd01 SF-IMS[4515]: [4515] pm:process [INFO] Unlocking sftunnel
May 2 11:17:36 ftd01 SF-IMS[4515]: [4515] pm:process [INFO] Started sftunnel (1944)
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] pm:process [INFO] Successfully set oom_score_adj of -500 for process sftunnel.
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:sf_peers [INFO] PEER INFO:
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:sf_peers [INFO] pinfo->sw_version 6.7.0
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:sf_peers [INFO] pinfo->sw_build 65
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:sftunnel_config [INFO] ROLE=1
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:sf_peers [INFO] Using a 20 entry queue for fmc.example.com - 8104
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:sf_peers [INFO] Using a 20 entry queue for fmc.example.com - 8121
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:stream_file [INFO] Stream CTX initialized for fmc.example.com
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:sftunnel_config [INFO] Update peers list for RPC
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:REG_CONFIG [INFO] Writing FMC map
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:REG_CONFIG [INFO] JSON Peer List: skip peer fmc.example.com, 1.
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:sftunnel_config [INFO] IPv4 is 10.0.35.101 (key '10.0.35.101') on eth0
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:sftunnel_config [INFO] IPv6 is 2a01:190:15fc:107:0:0:0:101 (key '2a01:190:15fc:107:0:0:0:101') on eth0
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:sftunnel_config [INFO] IPv4 is 169.254.1.2 (key '169.254.1.2') on tap_nlp
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:sftunnel_config [INFO] IPv6 is fd00:0:0:1::2 (key 'fd00:0:0:1::2') on tap_nlp
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:sftunnel_config [INFO] Local Peer supports multiple ports
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:sftunnel_config [INFO] Local Peer supports separate events connection
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:sftunnel_config [INFO] Management Interfaces configuration changed
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:sftunnel [INFO] Starting UEC tunnel service
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:DataMessaging_EventQueue [CRITICAL] Error opening Dummy!
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:DataMessaging_EventQueue [INFO] Event QoS started successfully!
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:TunnelService [INFO] Loaded service module UEChanneld
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:sftunnel [INFO] Control socket '/ngfw/var/sf/peers/sftunnel.sox': 7 is listening...
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:REG_CONFIG [WARN] Unable to create /ngfw/var/sf/peers/ directory: File exists
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:REG_CONFIG [WARN] Unable to create /ngfw/var/sf/peers_unregistered/ directory: File exists
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:REG_CONFIG [WARN] Unable to create /ngfw/var/sf/peers_failed/ directory: File exists
May 2 11:17:36 ftd01 SF-IMS[1944]: [1944] sftunneld:REG_CONFIG [WARN] Unable to create /ngfw/var/sf/peers_pending// directory: File exists
May 2 11:17:36 ftd01 SF-IMS[1944]: [1951] sftunneld:sf_peers [INFO] Peer fmc.example.com needs a single connection
May 2 11:17:36 ftd01 SF-IMS[1944]: [1951] sftunneld:SFUtil [INFO] Address type not found from inet_pton for fmc.example.com invoking getDNSRecordsbyname
May 2 11:17:36 ftd01 SF-IMS[1944]: [1951] sftunneld:SFUtil [INFO] Looking up DNS records for [fmc.example.com]
May 2 11:17:36 ftd01 SF-IMS[1944]: [1951] sftunneld:SFUtil [INFO] Found [2] no of addresses from getDNSRecordsbyname
May 2 11:17:36 ftd01 SF-IMS[1944]: [1951] sftunneld:sf_connections [INFO] Start connection to : fmc.example.com (wait 0 seconds is up)
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_peers [INFO] Peer fmc.example.com needs a single connection
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_ssl [INFO] Connect to fmc.example.com on port 8305 - eth0
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_ssl [INFO] Initiate connection using resolved_ip_list having [2] entries (via eth0)
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_ssl [INFO] Initiate IPv6 type connection
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_ssl [INFO] Initiate IPv4 type connection
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_ssl [INFO] Initiate IPv4 connection from resolved_ip_list to 10.0.35.100 (via eth0)
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_ssl [INFO] Initiating IPv4 connection to 10.0.35.100:8305/tcp
May 2 11:17:36 ftd01 SF-IMS[1944]: [1950] sftunneld:tunnsockets [INFO] Started listening on port 8305 IPv4(10.0.35.101) eth0
May 2 11:17:36 ftd01 SF-IMS[1944]: [1950] sftunneld:tunnsockets [INFO] Started listening on port 8305 IPv6 (2a01:190:15fc:107:0:0:0:101) eth0
May 2 11:17:36 ftd01 SF-IMS[1944]: [1950] sftunneld:tunnsockets [INFO] Started listening on port 8305 IPv4(169.254.1.2) tap_nlp
May 2 11:17:36 ftd01 SF-IMS[1944]: [1950] sftunneld:tunnsockets [INFO] Started listening on port 8305 IPv6 (fd00:0:0:1::2) tap_nlp
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_ssl [INFO] Wait to connect to 8305 (IPv4): 10.0.35.100
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_ssl [INFO] Connected to 10.0.35.100 from resolved_ip_list (port 8305) (IPv4)
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_ssl [INFO] Successfully connected using SSL to: 'fmc.example.com'
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_ssl [INFO] Peer fmc.example.com supports separate events connection
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_ssl [INFO] Peer fmc.example.com registration is complete remotely
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_ssl [INFO] Connect: AUTHENTICATED peer '10.0.35.100'
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_peers [INFO] Peer fmc.example.com needs a single connection
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_ssl [INFO] Connect: Will later need a second (events) connection to peer 'fmc.example.com'
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_ssl [INFO] Connect: Start child thread for peer 'fmc.example.com'
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_connections [INFO] HandlePeerConnection....
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_channel [INFO] >>>>>>> initChannels peer: fmc.example.com <<<<<<
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:stream_file [INFO] Stream CTX destroyed for fmc.example.com
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_ssl [INFO] VERIFY ssl_verify_callback_final ok=1!
May 2 11:17:36 ftd01 SF-IMS[1022]: Last message '[1952] sftunneld:sf_' repeated 1 times, suppressed by syslog-ng on ftd01.example.com
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_ssl [INFO] Found Peer by CERT subject_title=773010ea-3df2-11ea-b8af-7f5efeab3d9e
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_ssl [INFO] The peer(server) fmc.example.com renegotiated certificate successfully
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_connections [INFO] Socket '/ngfw/var/sf/peers/773010ea-3df2-11ea-b8af-7f5efeab3d9e/conn.sox': 14 is accepting services.
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:UEChannel [INFO] In init for UEChanneld to 773010ea-3df2-11ea-b8af-7f5efeab3d9e
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_heartbeat [INFO] UE Priority Event Channel 0 Service is published for peer fmc.example.com
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_peers [INFO] Using a 750 entry queue for fmc.example.com - 9100
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_channel [INFO] Peer fmc.example.com. SWITCH SERVICE 9100 CHANNEL 2
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:TunnelService [INFO] Spawned an instance thread for UEChanneld - 9100 to 773010ea-3df2-11ea-b8af-7f5efeab3d9e
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_heartbeat [INFO] UE Priority Event Channel 1 Service is published for peer fmc.example.com
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_peers [INFO] Using a 750 entry queue for fmc.example.com - 9101
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_channel [INFO] Peer fmc.example.com. SWITCH SERVICE 9101 CHANNEL 2
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:TunnelService [INFO] Spawned an instance thread for UEChanneld - 9101 to 773010ea-3df2-11ea-b8af-7f5efeab3d9e
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_connections [INFO] Connected UEC Services...
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:stream_file [INFO] Stream CTX initialized for fmc.example.com
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:ssl_mac [INFO] Set to Challenge: Peer (773010ea-3df2-11ea-b8af-7f5efeab3d9e)
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_connections [INFO] Peer fmc.example.com main thread started
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_connections [INFO] Need to send SW version and Published Services to fmc.example.com
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_channel [INFO] >> ChannelState do_dataio_for_heartbeat peer fmc.example.com / channelA / CONTROL [ msgSock & ssl_context ] <<
May 2 11:17:36 ftd01 SF-IMS[1944]: [1954] sftunneld:UEChannel [INFO] Loading DE configuration for service = 9101
May 2 11:17:36 ftd01 SF-IMS[1944]: [1954] sftunneld:UEChannel [INFO] Loading file processing config for service 9101
May 2 11:17:36 ftd01 SF-IMS[1944]: [1954] sftunneld:UEChannel [INFO] Loading VPN User config for service 9101
May 2 11:17:36 ftd01 SF-IMS[1944]: [1954] sftunneld:UEChannel [INFO] Ready for events type 10 with 5 instances
May 2 11:17:36 ftd01 SF-IMS[1944]: [1954] sftunneld:UEChannel [INFO] Ready for events type 17 with 3 instances
May 2 11:17:36 ftd01 SF-IMS[1944]: [1954] sftunneld:UEChannel [INFO] Ready for events type 12 with 3 instances
May 2 11:17:36 ftd01 SF-IMS[1944]: [1954] sftunneld:UEChannel [INFO] Ready for events type 11 with 3 instances
May 2 11:17:36 ftd01 SF-IMS[1944]: [1954] sftunneld:UEChannel [INFO] Ready for events type 1 with 3 instances
May 2 11:17:36 ftd01 SF-IMS[1944]: [1953] sftunneld:UEChannel [INFO] Loading DE configuration for service = 9100
May 2 11:17:36 ftd01 SF-IMS[1944]: [1953] sftunneld:UEChannel [INFO] Loading file processing config for service 9100
May 2 11:17:36 ftd01 SF-IMS[1944]: [1953] sftunneld:UEChannel [INFO] Loading VPN User config for service 9100
May 2 11:17:36 ftd01 SF-IMS[1944]: [1953] sftunneld:UEChannel [INFO] Ready for events type 20 with 1 instances
May 2 11:17:36 ftd01 SF-IMS[1944]: [1953] sftunneld:UEChannel [INFO] Ready for events type 16 with 3 instances
May 2 11:17:36 ftd01 SF-IMS[1944]: [1953] sftunneld:UEChannel [INFO] Ready for events type 15 with 3 instances
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_connections [INFO] Accepting a service connection..
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:control_services [INFO] Successfully Send Interfaces info to peer fmc.example.com over eth0
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_ch_util [INFO] Skip unregistered service
May 2 11:17:36 ftd01 SF-IMS[1022]: Last message '[1952] sftunneld:sf_' repeated 1 times, suppressed by syslog-ng on ftd01.example.com
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_heartbeat [INFO] Message Broker Service is published for peer fmc.example.com
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_peers [INFO] Using a 20 entry queue for fmc.example.com - 8306
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_connections [INFO] Accepting a service connection..
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_heartbeat [INFO] IP(NTP) Service is published for peer fmc.example.com.
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_peers [INFO] Using a 750 entry queue for fmc.example.com - 8400
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_connections [INFO] Accepting a service connection..
May 2 11:17:36 ftd01 SF-IMS[1945]: [1958] sfmgr:sfmanager [INFO] Established connection to sftunnel for peer fmc.example.com (fd 6)
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_heartbeat [INFO] RPC Service is published for peer fmc.example.com.
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_peers [INFO] Using a 20 entry queue for fmc.example.com - 6666
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_connections [INFO] Need to send SW version and Published Services to fmc.example.com
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_peers [INFO] Confirm RPC service in CONTROL channel
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_channel [INFO] >> ChannelState do_dataio_for_heartbeat peer fmc.example.com / channelA / CONTROL [ msgSock & ssl_context ] <<
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_connections [INFO] Accepting a service connection..
May 2 11:17:36 ftd01 SF-IMS[1022]: Last message '[1952] sftunneld:sf_' repeated 1 times, suppressed by syslog-ng on ftd01.example.com
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_heartbeat [INFO] Service 7000 is published for peer fmc.example.com
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_peers [INFO] Using a 750 entry queue for fmc.example.com - 7000
May 2 11:17:36 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_channel [INFO] Peer fmc.example.com. SWITCH SERVICE 7000 CHANNEL 2
May 2 11:17:37 ftd01 SF-IMS[1944]: [1944] sftunneld:SYNC_PROC [INFO] ProcessSyncConfig : manager
May 2 11:17:37 ftd01 SF-IMS[1944]: [1944] sftunneld:SYNC_PROC [INFO] ProcessSyncConfig : SYNC2MANAGER
May 2 11:17:37 ftd01 SF-IMS[1944]: [1944] sftunneld:SYNC_PROC [INFO] ProcessSyncConfig : source
May 2 11:17:37 ftd01 SF-IMS[1944]: [1944] sftunneld:SYNC_PROC [INFO] SYNC:SRC=/var/sf/sync
May 2 11:17:37 ftd01 SF-IMS[1944]: [1944] sftunneld:SYNC_PROC [INFO] ProcessSyncConfig : GETFROMMANAGER
May 2 11:17:37 ftd01 SF-IMS[1944]: [1944] sftunneld:SYNC_PROC [INFO] ProcessSyncConfig : destination
May 2 11:17:37 ftd01 SF-IMS[1944]: [1944] sftunneld:SYNC_PROC [INFO] DEVICE:DEST=(null)
May 2 11:17:37 ftd01 SF-IMS[1944]: [1944] sftunneld:SYNC_PROC [INFO] SYNCDEST_FMC_DEVICE add HASH
May 2 11:17:37 ftd01 SF-IMS[1944]: [1944] sftunneld:SYNC_PROC [INFO] ProcessSyncConfig : managed
May 2 11:17:37 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_connections [INFO] Accepting a service connection..
May 2 11:17:37 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_heartbeat [INFO] Identity Service is published for peer fmc.example.com
May 2 11:17:37 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_peers [INFO] Using a 20 entry queue for fmc.example.com - 7770
May 2 11:17:37 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_heartbeat [INFO] Malware Lookup Service is published for peer fmc.example.com.
May 2 11:17:37 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_peers [INFO] Using a 750 entry queue for fmc.example.com - 7700
May 2 11:17:37 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_channel [INFO] Peer fmc.example.com. SWITCH SERVICE 7700 CHANNEL 2
May 2 11:17:38 ftd01 SF-IMS[1944]: [1952] sftunneld:control_services [INFO] Interface eth0 from fmc.example.com supports 'control events'
May 2 11:17:38 ftd01 SF-IMS[1944]: [1952] sftunneld:control_services [INFO] Interface eth0 from fmc.example.com supports events
May 2 11:17:38 ftd01 SF-IMS[1944]: [1952] sftunneld:control_services [INFO] Interface eth0 (10.0.35.100) from fmc.example.com is up
May 2 11:17:38 ftd01 SF-IMS[1944]: [1952] sftunneld:control_services [INFO] Peer fmc.example.com Notified that it is NOT configured for dedicated events interface
May 2 11:17:38 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_connections [INFO] Need to send SW version and Published Services to fmc.example.com
May 2 11:17:38 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_peers [INFO] Confirm RPC service in CONTROL channel
May 2 11:17:38 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_channel [INFO] >> ChannelState do_dataio_for_heartbeat peer fmc.example.com / channelA / CONTROL [ msgSock & ssl_context ] <<
May 2 11:17:38 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_heartbeat [INFO] Saved SW VERSION from peer fmc.example.com (6.7.0)
May 2 11:17:38 ftd01 SF-IMS[1944]: [1952] sftunneld:ssl_mac [INFO] Peer 773010ea-3df2-11ea-b8af-7f5efeab3d9e send version 6.7.0 - send hmac message
May 2 11:17:38 ftd01 SF-IMS[1944]: [1952] sftunneld:ssl_mac [INFO] Build to send body of HMAC AUTH message:'{ "flags": 16777216, "uuid": "457d932a-3dfb-11ea-9b36-8a42de410c5c", "hmac_hash": "c345c459f3267fe4f1806c4de598ab16ef97caa2937e6dd5f592402ac158ef4a2cc6134c70e2512f2a76375eab572c5836cbbda5f0b59c7312ebe25505526947", "hmac_hash_default": "61bbbde9cfd33f60815173f7322af03427d48ae4022ec7ace9bc6f145e5b04755c7653eda44cf42c65521b82893db683fe148659f804ed14567831d15cdc8d49"}'
May 2 11:17:38 ftd01 SF-IMS[1944]: [1952] sftunneld:SYNC_PROC [INFO] Time to send UpdateMessage to 773010ea-3df2-11ea-b8af-7f5efeab3d9e (8296)
May 2 11:17:38 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_connections [INFO] Process HMAC Auth message for Peer 773010ea-3df2-11ea-b8af-7f5efeab3d9e
May 2 11:17:38 ftd01 SF-IMS[1944]: [1952] sftunneld:ssl_mac [INFO] GOT HMAC AUTH message json:'{ "flags": 16777216, "uuid": "773010ea-3df2-11ea-b8af-7f5efeab3d9e", "hmac_hash": "", "hmac_hash_default": "5f773567da3eec795053b1294d2cf4b39608c8603b1b03edd1f1de2dac838c6d64001e887a6e8b28ee3ac7cb05cae8fe2720137c1c87548d6d82eaf265c6a622"}'
May 2 11:17:38 ftd01 SF-IMS[1944]: [1952] sftunneld:ssl_mac [INFO] Peer 773010ea-3df2-11ea-b8af-7f5efeab3d9e supports explicit stale connection detection (HMAC challenge)
May 2 11:17:38 ftd01 SF-IMS[1944]: [1952] sftunneld:ssl_mac [INFO] Authorize Control channel
May 2 11:17:38 ftd01 SF-IMS[1944]: [1952] sftunneld:ssl_mac [INFO] (channel 1) HMAC Auth message MATCHED peer server cert!!!
May 2 11:17:38 ftd01 SF-IMS[1944]: [1952] sftunneld:ssl_mac [INFO] Authorize Event channel
May 2 11:17:38 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_heartbeat [INFO] Saved SW VERSION from peer fmc.example.com (6.7.0)
May 2 11:17:40 ftd01 SF-IMS[1944]: [1952] sftunneld:control_services [INFO] Purged pending requests to SFMGR for fmc.example.com
May 2 11:17:40 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_heartbeat [INFO] Saved SW VERSION from peer fmc.example.com (6.7.0)
May 2 11:17:40 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_heartbeat [INFO] (2)FORWARDED Product Info received from peer fmc.example.com to SFMGR
May 2 11:17:46 ftd01 SF-IMS[1944]: [1954] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/detection_engines/b2b3f6aa-3dfb-11ea-be9c-2066de410c5c/instance-3/unified_events-2-rna.log.1619881248
May 2 11:17:46 ftd01 SF-IMS[1944]: [1954] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/detection_engines/b2b3f6aa-3dfb-11ea-be9c-2066de410c5c/instance-2/unified_events-2-rna.log.1619881801
May 2 11:17:46 ftd01 SF-IMS[1944]: [1954] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/detection_engines/b2b3f6aa-3dfb-11ea-be9c-2066de410c5c/instance-1/unified_events-2-rna.log.1619881513
May 2 11:17:46 ftd01 SF-IMS[1944]: [1954] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/detection_engines/b2b3f6aa-3dfb-11ea-be9c-2066de410c5c/instance-3/ssl-certs-unified.log.1619896624
May 2 11:17:46 ftd01 SF-IMS[1944]: [1954] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/detection_engines/b2b3f6aa-3dfb-11ea-be9c-2066de410c5c/instance-2/ssl-certs-unified.log.1619905370
May 2 11:17:46 ftd01 SF-IMS[1944]: [1954] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/detection_engines/b2b3f6aa-3dfb-11ea-be9c-2066de410c5c/instance-1/ssl-certs-unified.log.1619930871
May 2 11:17:46 ftd01 SF-IMS[1944]: [1954] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/detection_engines/b2b3f6aa-3dfb-11ea-be9c-2066de410c5c/instance-3/ssl-stats-unified.log.1619906703
May 2 11:17:46 ftd01 SF-IMS[1944]: [1954] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/detection_engines/b2b3f6aa-3dfb-11ea-be9c-2066de410c5c/instance-2/ssl-stats-unified.log.1619907601
May 2 11:17:46 ftd01 SF-IMS[1944]: [1954] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/detection_engines/b2b3f6aa-3dfb-11ea-be9c-2066de410c5c/instance-1/ssl-stats-unified.log.1619909702
May 2 11:17:46 ftd01 SF-IMS[1944]: [1954] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/detection_engines/b2b3f6aa-3dfb-11ea-be9c-2066de410c5c/instance-3/unified_events-2.log.1619953374
May 2 11:17:46 ftd01 SF-IMS[1944]: [1954] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/detection_engines/b2b3f6aa-3dfb-11ea-be9c-2066de410c5c/instance-2/unified_events-2.log.1619945494
May 2 11:17:46 ftd01 SF-IMS[1944]: [1953] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/detection_engines/b2b3f6aa-3dfb-11ea-be9c-2066de410c5c/instance-3/unified_stats.1611169265
May 2 11:17:46 ftd01 SF-IMS[1944]: [1954] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/detection_engines/b2b3f6aa-3dfb-11ea-be9c-2066de410c5c/instance-1/unified_events-2.log.1619953311
May 2 11:17:46 ftd01 SF-IMS[1944]: [1954] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/file_processing/file-extract-w3.log.1619947152
May 2 11:17:46 ftd01 SF-IMS[1944]: [1953] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/detection_engines/b2b3f6aa-3dfb-11ea-be9c-2066de410c5c/instance-2/unified_stats.1611169529
May 2 11:17:46 ftd01 SF-IMS[1944]: [1953] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/detection_engines/b2b3f6aa-3dfb-11ea-be9c-2066de410c5c/instance-1/unified_stats.1611169606
May 2 11:17:46 ftd01 SF-IMS[1944]: [1953] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/detection_engines/b2b3f6aa-3dfb-11ea-be9c-2066de410c5c/instance-3/unified_events-1.log.1619947151
May 2 11:17:46 ftd01 SF-IMS[1944]: [1953] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/detection_engines/b2b3f6aa-3dfb-11ea-be9c-2066de410c5c/instance-2/unified_events-1.log.1619947146
May 2 11:17:46 ftd01 SF-IMS[1944]: [1953] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/detection_engines/b2b3f6aa-3dfb-11ea-be9c-2066de410c5c/instance-1/unified_events-1.log.1619939140
May 2 11:17:46 ftd01 SF-IMS[1944]: [1953] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/useridentity/unified_events-1-vpnsessions.log.1606323851
May 2 11:17:46 ftd01 SF-IMS[1944]: [1954] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/file_processing/file-extract-w2.log.1619886513
May 2 11:17:46 ftd01 SF-IMS[1944]: [1954] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/file_processing/file-extract-w1.log.1619947151
May 2 11:17:46 ftd01 SF-IMS[1944]: [1954] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/file_processing/file-extract-w0.log.1619947152
May 2 11:17:46 ftd01 SF-IMS[1944]: [1954] sftunneld:FileUtils [INFO] Opened input file /ngfw/var/sf/file_processing/file-extract-stats.log.1619902727
May 2 11:17:47 ftd01 SF-IMS[1944]: [1944] sftunneld:SYNC_PROC [INFO] Change in directory /ngfw/var/sf/sync detected (0 vs 1619913601)
May 2 11:17:47 ftd01 SF-IMS[1944]: [1952] sftunneld:SYNC_PROC [INFO] Got DIR_SYNC_ACK from peer 773010ea-3df2-11ea-b8af-7f5efeab3d9e
May 2 11:17:48 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_connections [INFO] Accepting a service connection..
May 2 11:17:48 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_heartbeat [INFO] CSM_CCM service is published for peer fmc.example.com
May 2 11:17:48 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_peers [INFO] Using a 750 entry queue for fmc.example.com - 9009
May 2 11:17:48 ftd01 SF-IMS[1944]: [1952] sftunneld:sf_channel [INFO] Peer fmc.example.com. SWITCH SERVICE 9009 CHANNEL 2 Restarting Processes by Type
Another way to restart processes is by specifying a type. The only usecase I have come across for the RestartByType subcommand is for restarting the snort engine. Restarting snort can be a neccessary procedure for activating certain changes (e.g. after a manual cleanup) or could be a troubleshooting step – I sometimes resort to this step if unexplainable behavior occurs within the layer-7 engine.
pmtool restartByType DetectionEngineWarning
Restarting the DetectionEngine may lead to a brief (0.1-3.0sec in my experience) dataplane outage so proceed with caution. In case you have a high availability pair restart snort on the passive unit and execute a failover for a more graceful non-disruptive option
Disabling & Enabling Processes
Under normal circumstances there should be no need to disable any system services. The only reason to do so is for debugging purposes. Some processes like adi, CloudAgent, sla or SSEConnector provide additional debug flags that can be utilized to gain more insight of what is happening behind the scenes.
For a brief demonstration we will disable the adi process on FMC and run it in debug mode
Step 01: Disable adi process
root@ftd01:/home/admin# pmtool disablebyid adiStep 02: Verify that adi process is user disabled and not running
root@ftd01:/home/admin# pmtool status | grep adiadi (normal) - User Disabled
Command: /ngfw/usr/local/sf/bin/adi
PID File: /ngfw/var/sf/run/adi.pid
Command: /ngfw/usr/local/sf/bin/beakerd --module-path=/ngfw/usr/local/sf/lib64 --log-file=/ngfw/var/log/beakerd.log --log-level=info --cfgdir=/ngfw/etc/sf/beakerd --pidfile=/ngfw/var/sf/run/beakerd.pid --enable-module=updater --enable-module=nikita --datadir=/ngfw/etc/sf/beakerd --listen=/ngfw/var/tmp/beaker_client.sock --listen=/ngfw/var/tmp/beaker_async_client.sock Step 04: Run adi in debug mode and send output to screen and /var/tmp/adi.log
adi --debug 2>&1 | tee /var/tmp/adi.logDebugging log output
May 02 11:55:44 ftd01 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:318:ProcessConfigGlobalSettings(): Parsing global settings
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:350:ProcessConfigGlobalSettings(): global_settings.max_active_auth_retries = 3
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:394:ProcessConfigGlobalSettings(): global_settings.linaProtocol = ipc
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:337:ProcessConfigGlobalSettings(): global_settings.cipher_key_file_path = /ngfw/etc/sf/ADI_conf_Encryption_Key.bin
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:363:ProcessConfigGlobalSettings(): global_settings.sendS2SVPNEvents = true
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:368:ProcessConfigGlobalSettings(): global_settings.sendRAVPNEvents = tunnel
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:501:ProcessConfigFPReplication(): fpreplication.mode = follower
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:263:ProcessKeyValuePair(): tenant.uid = 1
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:630:ProcessConfigTenant(): New tenant
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:666:ProcessConfigTenant(): tenant.realm.uid = 4
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:691:ProcessConfigRealm(): New realm
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:711:ProcessConfigRealm(): tenant.realm.uuid = 48916640-4e4a-11ea-bba2-9b7b2e356a46
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:723:ProcessConfigRealm(): tenant.realm.name = example.com
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:751:ProcessConfigRealm(): tenant.realm.realm_type = AD
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:763:ProcessConfigRealm(): tenant.realm.directory_username = [email protected]
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:775:ProcessConfigRealm(): tenant.realm.directory_password = d3p3nd3nc!h3!!0Nep59RwdvuJ6IA==
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:787:ProcessConfigRealm(): tenant.realm.ldap_user_naming_attribute = sAMAccountName
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:799:ProcessConfigRealm(): tenant.realm.ldap_user_search_base = ou=com,ou=example,dc=example,dc=com
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:811:ProcessConfigRealm(): tenant.realm.ldap_group_attribute = member
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:883:ProcessConfigRealm(): tenant.realm.ldap_group_search_base = ou=groups,ou=com,ou=example,dc=example,dc=com
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:859:ProcessConfigRealm(): tenant.realm.iv_ldap_value = d3p3nd3nc!h3!!0Nep59RwdvuJ6IA==
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:871:ProcessConfigRealm(): tenant.realm.iv_ad_value = d3p3nd3nc!h3!!0Nep59RwdvuJ6IA==
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:823:ProcessConfigRealm(): tenant.realm.active_directory_domain = example.com
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:847:ProcessConfigRealm(): tenant.realm.active_directory_password = d3p3nd3nc!h3!!0Nep59RwdvuJ6IA==
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:998:ProcessConfigDirectory(): New directory
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:1018:ProcessConfigDirectory(): tenant.realm.directory.host = dc01.example.com
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:1031:ProcessConfigDirectory(): tenant.realm.directory.port = 389
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:1053:ProcessConfigDirectory(): tenant.realm.directory.encryption = none
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:1072:ProcessConfigDirectory(): tenant.realm.directory.timeout_seconds = 60
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:998:ProcessConfigDirectory(): New directory
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:1018:ProcessConfigDirectory(): tenant.realm.directory.host = dc02.example.com
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:1031:ProcessConfigDirectory(): tenant.realm.directory.port = 389
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:1053:ProcessConfigDirectory(): tenant.realm.directory.encryption = none
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:1072:ProcessConfigDirectory(): tenant.realm.directory.timeout_seconds = 60
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:config [DEBUG] config.cpp:212:ProcessConfiguration(): Configuration read
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:adi.ADIStateMachine [INFO] ADIStateMachine.cpp:54:moveTo(): ADI state moved to ADI_STOPPED
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:adi.ZMQWorker [INFO] ZMQWorker.cpp:76:start(): Added ZMQ worker thread id:7f79367fc700 object: 0x5558b87a3930
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:adi.ZMQWorker [INFO] ZMQWorker.cpp:76:start(): Added ZMQ worker thread id:7f79357fa700 object: 0x5558b877fa10
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:adi.ZMQWorker [INFO] ZMQWorker.cpp:76:start(): Added ZMQ worker thread id:7f7934ff9700 object: 0x5558b8807d40
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:adi.ZMQWorker [INFO] ZMQWorker.cpp:76:start(): Added ZMQ worker thread id:7f7927fff700 object: 0x5558b87a4300
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:adi.ZMQWorker [INFO] ZMQWorker.cpp:76:start(): Added ZMQ worker thread id:7f79277fe700 object: 0x5558b8807cb0
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:adi.ZMQWorker [INFO] ZMQWorker.cpp:76:start(): Added ZMQ worker thread id:7f7926ffd700 object: 0x5558b87a5380
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:adi.ZMQWorker [INFO] ZMQWorker.cpp:76:start(): Added ZMQ worker thread id:7f79267fc700 object: 0x5558b87a7970
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:adi.ZMQWorker [INFO] ZMQWorker.cpp:76:start(): Added ZMQ worker thread id:7f7925ffb700 object: 0x5558b87a71e0
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:adi.ZMQWorker [INFO] ZMQWorker.cpp:76:start(): Added ZMQ worker thread id:7f79257fa700 object: 0x5558b876bae0
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:adi.ZMQWorker [INFO] ZMQWorker.cpp:76:start(): Added ZMQ worker thread id:7f7924ff9700 object: 0x5558b876be80
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:adi.ZMQWorker [DEBUG] ZMQWorker.cpp:96:start(): Widened permissions for /tmp/adireq to 777.
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:ADI [DEBUG] adi.cpp:203:setVPNProcessing(): Starting S2S VPN event handler due to configuration change
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:ADI [DEBUG] adi.cpp:210:setVPNProcessing(): Starting S2S VPN event consumer due to configuration change
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:ADI [DEBUG] adi.cpp:239:setVPNProcessing(): Starting RA VPN event handler due to configuration change
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:DataMessaging_EventQueue [DEBUG] EventQueue_impl.cpp:1990:ParseEventQueues(): Event Queues not configured in /etc/sf/SFDataCorrelator.conf, using internal defaults!
May 02 11:55:44 SF-IMS[10482]: [10500] ADI:VPN Event [DEBUG] vpnEventHandler.cpp:598:getSFTunnelConfiguration(): Processing file /ngfw/etc/sf/sftunnel.conf
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute UECHelloDR lookup returned 6
May 02 11:55:44 SF-IMS[10482]: [10500] ADI:VPN Event [DEBUG] vpnEventHandler.cpp:511:ProcessTunnelKeyValuePair(): Setting VPN event device UUID to 457d932a-3dfb-11ea-9b36-8a42de410c5c
May 02 11:55:44 SF-IMS[10482]: [10500] ADI:VPN Event [DEBUG] vpnEventHandler.cpp:561:ProcessTunnelKeyValuePair(): Adding peer 773010ea-3df2-11ea-b8af-7f5efeab3d9e
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute UECReplyDR lookup returned 7
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute UECPriorityStatEvent lookup returned 10
May 02 11:55:44 SF-IMS[10482]: [10500] ADI:VPN Event [DEBUG] vpnEventHandler.cpp:293:processEvents(): IP: 457d932a-3dfb-11ea-9b36-8a42de410c5c, manager List '773010ea-3df2-11ea-b8af-7f5efeab3d9e'
May 02 11:55:44 SF-IMS[10482]: [10500] ADI:VPN Event [DEBUG] vpnEventHandler.cpp:300:processEvents(): Current event count: 0
May 02 11:55:44 SF-IMS[10482]: [10500] ADI:VPN Event [DEBUG] vpnEventHandler.cpp:374:processEvents(): Did FMCRefresh
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:DataMessaging_EventQueue [DEBUG] EventQueue_impl.cpp:2318:ProcessLLConfigFile(): tid config: enable_obs=1, send_obs_to_sfdc=0
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:DataMessaging_EventQueue [DEBUG] EventQueue_impl.cpp:2318:ProcessLLConfigFile(): tid config: enable_obs=1, send_obs_to_sfdc=1
May 02 11:55:44 SF-IMS[10482]: [10500] ADI:VPN Event [DEBUG] vpnEventHandler.cpp:388:processEvents(): Sending events with function: Remote::SF::VPN::setFTDStatus({targets=>['773010ea-3df2-11ea-b8af-7f5efeab3d9e']}, '457d932a-3dfb-11ea-9b36-8a42de410c5c', [], 3)
May 02 11:55:44 SF-IMS[10482]: [10500] ADI:Forker [DEBUG] forker.cpp:25:run(): Forker::run() calling cmd '/ngfw/usr/local/sf/bin/send_vpn_events.sh' with args:[/ngfw/usr/local/sf/bin/send_vpn_events.sh,perl,Remote::SF::VPN::setFTDStatus({targets=>['773010ea-3df2-11ea-b8af-7f5efeab3d9e']}, '457d932a-3dfb-11ea-9b36-8a42de410c5c', [], 3)]
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:DataMessaging_EventQueue [INFO] EventQueue_impl.cpp:2626:DataMessaging_InitEventQueues(): Event QoS started successfully!
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:DataMessaging_EventQueue [DEBUG] EventQueue_impl.cpp:2627:DataMessaging_InitEventQueues(): Started Event thread Success
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute INT32 lookup returned 7
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute Deprecated_IPMask lookup returned 24
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute Deprecated_UserService lookup returned 26
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute INT32 lookup returned 7
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute INT32 lookup returned 7
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute Deprecated_VulnAck lookup returned 22
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute VulnList lookup returned 85
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute VulnList lookup returned 85
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute AttributeListItem lookup returned 39
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute AttributeAddress lookup returned 146
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute IPRangeSpec lookup returned 141
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute MacSpec lookup returned 63
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute UserClientApp lookup returned 138
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute IPRangeSpec lookup returned 141
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute MacSpec lookup returned 63
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute IPRangeSpec lookup returned 141
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute UserService lookup returned 76
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute IPRangeSpec lookup returned 141
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute MacSpec lookup returned 63
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute VulnAck lookup returned 124
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute IPRangeSpec lookup returned 141
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute IPRangeSpec lookup returned 141
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute UserProtocol lookup returned 57
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute HostMAC lookup returned 95
May 2 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute ServiceInfo lookup returned 117
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute Payload lookup returned 123
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute FullServiceInfo lookup returned 106
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute FullServiceInfo lookup returned 106
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute FullServiceInfo lookup returned 106
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute FullServiceInfo lookup returned 106
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute VulnList lookup returned 85
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute VulnList lookup returned 85
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute VulnList lookup returned 85
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute Payload lookup returned 123
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute FullServiceSubtype lookup returned 51
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute INT32 lookup returned 7
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute StringInfo lookup returned 35
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute Payload lookup returned 123
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute VulnList lookup returned 85
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute ServiceSubtype lookup returned 1
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute Payload lookup returned 123
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute IPRangeSpec lookup returned 141
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute DeviceInfo lookup returned 131
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute IPRangeSpec lookup returned 141
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute FixList lookup returned 67
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute IPRangeSpec lookup returned 141
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute HostService lookup returned 103
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute HostService lookup returned 103
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute PndProtocol lookup returned 4
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute PndProtocol lookup returned 4
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute HostMAC lookup returned 95
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute HostClientApp lookup returned 122
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute ScanVuln lookup returned 109
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute genericScanResults lookup returned 108
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute UserProduct lookup returned 134
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute IPRangeSpec lookup returned 141
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute HostIP lookup returned 143
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute OSFP lookup returned 130
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute FullHostService lookup returned 104
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute FullHostService lookup returned 104
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute PndProtocol lookup returned 4
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute PndProtocol lookup returned 4
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute HostMAC lookup returned 95
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute FullHostClientApp lookup returned 112
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute VulnList lookup returned 85
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute VulnList lookup returned 85
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute VulnList lookup returned 85
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute AttributeValue lookup returned 48
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute IOCState lookup returned 150
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute VPNSession lookup returned 166
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:RNASerializeLib [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/sfrnacommon/serialize/serialize.c:3785:InitRNASerialize(): Got 171 for FlowStats
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:RNASerializeLib [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/sfrnacommon/serialize/serialize.c:3785:InitRNASerialize(): Got 139 for HostTracker
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:RNASerializeLib [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/sfrnacommon/serialize/serialize.c:3785:InitRNASerialize(): Got 103 for HostService
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:RNASerializeLib [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/sfrnacommon/serialize/serialize.c:3785:InitRNASerialize(): Got 145 for RNADHCPInfo
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:RNASerializeLib [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/sfrnacommon/serialize/serialize.c:3785:InitRNASerialize(): Got 122 for HostClientApp
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:RNASerializeLib [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/sfrnacommon/serialize/serialize.c:3785:InitRNASerialize(): Got 130 for OSFP
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:RNASerializeLib [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/sfrnacommon/serialize/serialize.c:3785:InitRNASerialize(): Got 53 for OS
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:RNASerializeLib [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/sfrnacommon/serialize/serialize.c:3785:InitRNASerialize(): Got 95 for HostMAC
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:RNASerializeLib [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/sfrnacommon/serialize/serialize.c:3785:InitRNASerialize(): Got 14 for VLAN
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:RNASerializeLib [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/sfrnacommon/serialize/serialize.c:3785:InitRNASerialize(): Got 35 for StringInfo
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:RNASerializeLib [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/sfrnacommon/serialize/serialize.c:3785:InitRNASerialize(): Got 37 for ServiceBanner
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:RNASerializeLib [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/sfrnacommon/serialize/serialize.c:3785:InitRNASerialize(): Got 167 for UserLoginInfo
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:RNASerializeLib [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/sfrnacommon/serialize/serialize.c:3785:InitRNASerialize(): Got 96 for SecondaryHostUpdate
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute INT32 lookup returned 6
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute Unified2UserMapUpdate lookup returned 11
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute INT32 lookup returned 6
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute INT32 lookup returned 6
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute MACADDR lookup returned 17
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute String lookup returned 0
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute INT32 lookup returned 6
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:SFSerialize [DEBUG] sfserialize.c:847:SFSerialize_Init(): Attribute INT32 lookup returned 6
May 02 11:55:44 SF-IMS[10482]: [10482] ADI:ADI [DEBUG] adi.cpp:246:setVPNProcessing(): Starting RA VPN event consumer due to configuration change
May 02 11:55:45 SF-IMS[10482]: [10500] ADI:Forker [DEBUG] forker.cpp:48:run(): normal termination? 1, exit status: 0
May 02 11:55:45 SF-IMS[10482]: [10500] ADI:VPN Event [INFO] vpnEventHandler.cpp:410:processEvents(): Sent 1 VPN events to manager
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.ADIStateMachine [INFO] ADIStateMachine.cpp:54:moveTo(): ADI state moved to ADI_READY
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.RealmContainer [DEBUG] RealmContainer.cpp:208:DoInit(): ADI Process Processing 1 tenants from configuration.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.RealmContainer [DEBUG] RealmContainer.cpp:213:DoInit(): ADI Process Processing 1 realms from next tenant.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.RealmContainer [DEBUG] RealmContainer.cpp:217:DoInit(): ADI Process constructing next realm.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.RealmContainer [DEBUG] RealmContainer.cpp:134:populateModelRealmFromConfigRealm(): Decrypting active directory Password…
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.RealmContainer [DEBUG] RealmContainer.cpp:142:populateModelRealmFromConfigRealm(): Success!
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.RealmContainer [DEBUG] RealmContainer.cpp:181:populateModelRealmFromConfigRealm(): Decrypting directory Password…
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.RealmContainer [DEBUG] RealmContainer.cpp:189:populateModelRealmFromConfigRealm(): Success!
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.RealmContainer [DEBUG] RealmContainer.cpp:181:populateModelRealmFromConfigRealm(): Decrypting directory Password…
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.RealmContainer [DEBUG] RealmContainer.cpp:189:populateModelRealmFromConfigRealm(): Success!
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.AdRealm [DEBUG] AdRealm.cpp:600:onSendStatus(): onSendStatus: Sending ZMQ message for realm 4 : REALM_UNCONFIGURED
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.ZMQController [DEBUG] Controller.cpp:31:send(): Sent control message
May 02 11:55:45 SF-IMS[10482]: [10487] ADI:adi.ZMQServer [DEBUG] ZMQServer.cpp:352:processMessage(): Found data to broadcast result on subject: realm_status recv_result: 1
May 02 11:55:45 SF-IMS[10482]: [10487] ADI:adi.ZMQServer [DEBUG] ZMQServer.cpp:359:processMessage(): Sending broadcast response
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.ZMQController [DEBUG] Controller.cpp:38:send(): Received control response
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.Realm [DEBUG] Realm.cpp:102:validate(): Directory: ldap://dc01.example.com:389, Validating At: 1619956545
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.Directory [INFO] Directory.cpp:120:changeStatus(): Directory server ldap://dc01.example.com:389 changed state to up
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.Realm [DEBUG] Realm.cpp:102:validate(): Directory: ldap://dc01.example.com:389, Validating At: 1619956545
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.Realm [DEBUG] Realm.cpp:102:validate(): Directory: ldap://dc02.example.com:389, Validating At: 1619956545
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.Directory [INFO] Directory.cpp:120:changeStatus(): Directory server ldap://dc02.example.com:389 changed state to up
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.Realm [DEBUG] Realm.cpp:102:validate(): Directory: ldap://dc02.example.com:389, Validating At: 1619956545
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.AdRealm [INFO] AdRealm.cpp:159:configure(): ad: computer dn=cn=FTD01,cn=Computers,dc=ONG,dc=LAB
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.LdapRealm [WARN] LdapRealm.cpp:610:ldapSearch(): ldapParsePageControl: Control not found
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.LdapRealm [DEBUG] LdapRealm.cpp:647:ldapSearch(): ldap: search returned (1) result pages.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.AdRealm [DEBUG] AdRealm.cpp:214:findNetBIOSName(): ad: Found naming context CN=Configuration,DC=example,DC=com from Realm4(AD)_ldap://dc01.example.com:389
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.LdapRealm [DEBUG] LdapRealm.cpp:647:ldapSearch(): ldap: search returned (1) result pages.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.AdRealm [DEBUG] AdRealm.cpp:224:findNetBIOSName(): Found dns attribute example.com in cn=example,cn=partitions,cn=configuration,dc=example,dc=com, matching against example.com
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.LdapRealm [DEBUG] LdapRealm.cpp:647:ldapSearch(): ldap: search returned (1) result pages.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.AdRealm [DEBUG] AdRealm.cpp:233:findNetBIOSName(): Found netbios name ONG in cn=example,cn=partitions,cn=configuration,dc=example,dc=com
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.AdRealm [DEBUG] AdRealm.cpp:600:onSendStatus(): onSendStatus: Sending ZMQ message for realm 4 : REALM_UNCONFIGURED
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.ZMQController [DEBUG] Controller.cpp:31:send(): Sent control message
May 02 11:55:45 SF-IMS[10482]: [10487] ADI:adi.ZMQServer [DEBUG] ZMQServer.cpp:352:processMessage(): Found data to broadcast result on subject: realm_status recv_result: 1
May 02 11:55:45 SF-IMS[10482]: [10487] ADI:adi.ZMQServer [DEBUG] ZMQServer.cpp:359:processMessage(): Sending broadcast response
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.ZMQController [DEBUG] Controller.cpp:38:send(): Received control response
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.AdRealm [INFO] AdRealm.cpp:171:configure(): ad: successfully configured directory.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.RealmContainer [DEBUG] RealmContainer.cpp:236:DoInit(): RealmContainer populated from configuration, now contains 1 realms.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.Adi [DEBUG] Adi.cpp:153:configure(): configure connector.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:IseConnector [INFO] ISEConnector.cpp:216:configure(): Initializing Unified2 serialization library
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:IseConnector [DEBUG] ISEConnector.cpp:220:configure(): SXP Channel Factory
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.SXPDataProvider [DEBUG] SXPDataProvider.cpp:132:LoadBindings(): Loading bindings from files.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.SXPDataProvider [DEBUG] SXPDataProvider.cpp:152:LoadBindings(): Loading snapshot /var/sf/user_enforcement/sxp.snapshot.1604419773
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:Unified2Iterator [DEBUG] Unified2Iterator.c:407:Unified2Record_GetFromFile(): Opened /var/sf/user_enforcement/sxp.snapshot.1604419773
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.SXPDataProvider [DEBUG] SXPDataProvider.cpp:193:LoadBindings(): Loading update /var/sf/user_enforcement/sxp.1604419773
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:Unified2Iterator [DEBUG] Unified2Iterator.c:407:Unified2Record_GetFromFile(): Opened /var/sf/user_enforcement/sxp.1604419773
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.SXPEntryAppender [DEBUG] SXPEntryAppender.cpp:66:CreateArchiveFile(): initing archive file for type 1
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.SXPEntryAppender [DEBUG] SXPEntryAppender.cpp:305:UpdateRotatedFilesCounter(): Rotated files counter = 1
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:IseConnector [INFO] ISEConnector.cpp:343:createSXPFPReplicationFollowers(): mode Follower 127.0.0.2 5672
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:FPReplicationCommunicationRabbitFollower [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/fpreplication/src/FPReplicationCommunicationRabbitFollower.cpp:26:FPReplicationCommunicationRabbitFollower(): using b:sxp:457d932a-3dfb-11ea-9b36-8a42de410c5cas follower queue name
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:FPReplicationCommunicationRabbitFollower [INFO] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/fpreplication/src/FPReplicationCommunicationRabbitFollower.cpp:40:FPReplicationCommunicationRabbitFollower(): Creating new AMQP connection for consuming user/ip messages, with max priority: 0 and heartbeat: 30
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:RMQClient [DEBUG] RabbitMQClient.cpp:315:DoConnect(): b:sxp:457d932a-3dfb-11ea-9b36-8a42de410c5c connected to server successfully
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:IseConnector [INFO] ISEConnector.cpp:355:createSXPFPReplicationFollowers(): ReLoad SXP Filter
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:Tokenizer [DEBUG] /tmp/mesos/slaves/IMS/Pre-commit/90923-2388088/FTD/src/libraries/sfutil/parser/tokenizer.c:97:TokenizerInit(): Unable to open '/ngfw/var/sf/user_enforcement/network_filter.sxp.cur.773010ea-3df2-11ea-b8af-7f5efeab3d9e': No such file or directory
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.NetworkFilter [DEBUG] NetworkFilterUtils.cpp:192:ReLoadFilters(): read current filter
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:Tokenizer [DEBUG] /tmp/mesos/slaves/IMS/Pre-commit/90923-2388088/FTD/src/libraries/sfutil/parser/tokenizer.c:97:TokenizerInit(): Unable to open '/ngfw/var/sf/user_enforcement/network_filter.cfg': No such file or directory
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.NetworkFilter [DEBUG] NetworkFilterUtils.cpp:198:ReLoadFilters(): read config filter
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:IseConnector [DEBUG] ISEConnector.cpp:386:createSXPFPReplicationFollowers(): set follower filter for sxp
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.FPReplicationFollowerSXP [DEBUG] FPReplicationFollowerSXP.cpp:62:FPReplicationFollowerSXP(): Init FPReplicationFollowerSXP
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.FPReplicationFollowerSXP [INFO] FPReplicationFollowerSXP.cpp:63:FPReplicationFollowerSXP(): initializing filter at seq_no = 0
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:realm.join.retryer [DEBUG] RealmJoinRetryer.cpp:25:RealmJoinRetryer(): Starting realm join retryer worker thread.
May 02 11:55:45 SF-IMS[10482]: [10507] ADI:FPReplicationFollower [INFO] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/fpreplication/src/FPReplicationFollower.cpp:567:consume_messages(): fp replication follower consume messages-start
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.ZMQController [DEBUG] Controller.cpp:53:send(): Sent control message
May 02 11:55:45 SF-IMS[10482]: [10487] ADI:adi.ZMQServer [DEBUG] ZMQServer.cpp:366:processMessage(): Found lina control message on subject lina-control
May 02 11:55:45 SF-IMS[10482]: [10487] ADI:adi.ZMQServer [DEBUG] ZMQServer.cpp:165:createLinaChannel(): creating lina status channel
May 02 11:55:45 SF-IMS[10482]: [10487] ADI:adi.ZMQServer [DEBUG] ZMQServer.cpp:168:createLinaChannel(): lina protocol: ipc
May 02 11:55:45 SF-IMS[10482]: [10487] ADI:adi.ZMQServer [DEBUG] ZMQServer.cpp:184:createLinaChannel(): creating lina update channel
May 02 11:55:45 SF-IMS[10482]: [10487] ADI:adi.ZMQServer [DEBUG] ZMQServer.cpp:187:createLinaChannel(): lina protocol: ipc
May 02 11:55:45 SF-IMS[10482]: [10487] ADI:adi.ZMQServer [ERROR] ZMQServer.cpp:189:createLinaChannel(): Unable to subscribe to subject vpn-update
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.ZMQController [DEBUG] Controller.cpp:60:send(): Received control response
May 02 11:55:45 SF-IMS[10482]: [10507] ADI:FPReplicationFollower [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/fpreplication/src/FPReplicationFollower.cpp:576:consume_messages(): start consume_messages.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.ADIStateMachine [INFO] ADIStateMachine.cpp:54:moveTo(): ADI state moved to ADI_RUNNING
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.ISEConnectionSub [WARN] ISEConnectionSub.cpp:136:start(): Configuration doesn't have enough Pxgrid information
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:adi.RpcServer [INFO] RpcServer.cpp:204:start(): starting rpc server
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:infra.ev-rpc [DEBUG] server.cpp:436:registerSubjectDispatcher(): Added subject authenticate for server ADI.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:infra.ev-rpc [DEBUG] server.cpp:436:registerSubjectDispatcher(): Added subject directory test for server ADI.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:infra.ev-rpc [DEBUG] server.cpp:424:registerSubjectCallback(): Added subject ldap query for server ADI.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:infra.ev-rpc [DEBUG] server.cpp:424:registerSubjectCallback(): Added subject realm information feed for server ADI.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:infra.ev-rpc [DEBUG] server.cpp:424:registerSubjectCallback(): Added subject refresh request adi service session directory for server ADI.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:infra.ev-rpc [DEBUG] server.cpp:424:registerSubjectCallback(): Added subject refresh request ise security group feed for server ADI.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:infra.ev-rpc [DEBUG] server.cpp:424:registerSubjectCallback(): Added subject refresh request ise SXP feed for server ADI.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:infra.ev-rpc [DEBUG] server.cpp:424:registerSubjectCallback(): Added subject refresh request ise endpoint feed for server ADI.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:infra.ev-rpc [DEBUG] server.cpp:424:registerSubjectCallback(): Added subject ise Query Remediation Capabilities for server ADI.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:infra.ev-rpc [DEBUG] server.cpp:424:registerSubjectCallback(): Added subject ise remediation action request for server ADI.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:infra.ev-rpc [INFO] server.cpp:383:start(): Started server ADI, listening for clients.
May 02 11:55:45 SF-IMS[10482]: [10524] ADI:infra.ev-rpc [DEBUG] server.cpp:305:channelManagerThread(): Starting channelManagerThread for server ADI.
May 02 11:55:45 SF-IMS[10482]: [10482] ADI:ADI [INFO] adi.cpp:447:main(): Started
May 02 11:55:45 SF-IMS[10482]: [10523] ADI:infra.ev-rpc [DEBUG] server.cpp:276:channelUpdateThread(): Starting channelUpdateThread for server ADI.
May 02 11:55:46 SF-IMS[10482]: [10487] ADI:adi.ZMQServer [DEBUG] ZMQServer.cpp:236:initializeLinaChannel(): Initializing lina channel by sending hello
May 02 11:55:46 SF-IMS[10482]: [10487] ADI:adi.ZMQServer [DEBUG] ZMQServer.cpp:251:requestLinaSync(): Requesting lina vpn event sync
May 02 11:55:46 SF-IMS[10482]: [10487] ADI:adi.LinaEventHandler [DEBUG] LinaEventHandler.cpp:201:handleMessage(): Received VPN Sync response containing 6 events
May 02 11:55:46 SF-IMS[10482]: [10487] ADI:adi.SubscriberChannel [DEBUG] SubscriberChannel.cpp:39:sendMessage(): Sending request to ADI subscriber
May 02 11:55:46 SF-IMS[10482]: [10487] ADI:adi.SubscriberChannel [DEBUG] SubscriberChannel.cpp:56:sendMessage(): Receiving response from DataCorrelator
May 02 11:55:46 SF-IMS[10482]: [10487] ADI:adi.LinaEventHandler [DEBUG] LinaEventHandler.cpp:205:handleMessage(): Successfully sent bulksync to SFDataCorrelator
May 02 11:55:46 SF-IMS[10482]: [10508] ADI:realm.join.retryer [DEBUG] RealmJoinRetryer.cpp:90:threadWorkerFunction(): No more realm join retries needed, worker thread done.
May 02 11:55:46 SF-IMS[10482]: [10527] ADI:infra.ev-rpc [DEBUG] server.cpp:184:subscribe(): Subscribed client 0x5558b8710180 to subject adi service session directory.
May 02 11:55:46 SF-IMS[10482]: [10527] ADI:infra.ev-rpc [DEBUG] server.cpp:184:subscribe(): Subscribed client 0x5558b8710180 to subject ise security group feed.
May 02 11:55:46 SF-IMS[10482]: [10527] ADI:infra.ev-rpc [DEBUG] server.cpp:184:subscribe(): Subscribed client 0x5558b8710180 to subject ise endpoint feed.
May 02 11:55:46 SF-IMS[10482]: [10527] ADI:adi.RpcServer [DEBUG] RpcServer.cpp:295:realm_feed_subject_handler(): adding realm Info to feedrealm id = 4 domain = example.com short domain = ONG
May 02 11:55:46 SF-IMS[10482]: [10527] ADI:adi.RpcServer [INFO] RpcServer.cpp:344:triggerSecurityGroupBulkDownloadCallback(): fill SECURITY_GROUP_WIPE_ALL event
May 02 11:55:46 SF-IMS[10482]: [10527] ADI:adi.ISEConnection [DEBUG] ISEConnection.cpp:981:performEndpointProfileBulkDownload(): Postponing Endpoint Profile download until future connect.
May 02 11:55:46 SF-IMS[10482]: [10527] ADI:adi.ISEConnection [DEBUG] ISEConnection.cpp:1678:kickoffSessionsBulkDownload(): Postponing Sessions download until future connect.
May 02 11:56:00 SF-IMS[10482]: [10507] ADI:FPReplicationFollower [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/fpreplication/src/FPReplicationFollower.cpp:578:consume_messages(): consume_messages rval:1
May 02 11:56:00 SF-IMS[10482]: [10507] ADI:FPReplicationFollower [INFO] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/fpreplication/src/FPReplicationFollower.cpp:1458:publish_message_timeout_request(): requesting msg_timeout catchup
May 02 11:56:00 SF-IMS[10482]: [10507] ADI:FPReplicationFollower [INFO] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/fpreplication/src/FPReplicationFollower.cpp:757:request_catchup(): SXPFollower expecting: 16 requesting catchup, target seq_no: 0 ,req_id: 1 snapshot entry offset: 0
May 02 11:56:00 SF-IMS[10482]: [10507] ADI:FPReplicationFollower [INFO] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/fpreplication/src/FPReplicationFollower.cpp:792:request_catchup(): published catchup request
May 02 11:56:00 SF-IMS[10482]: [10507] ADI:FPReplicationFollower [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/fpreplication/src/FPReplicationFollower.cpp:1515:change_follower_state(): entering transient state: 2, setting timer to 1619956560
May 02 11:56:00 SF-IMS[10482]: [10507] ADI:FPReplicationFollower [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/fpreplication/src/FPReplicationFollower.cpp:576:consume_messages(): start consume_messages.
May 02 11:56:00 SF-IMS[10482]: [10507] ADI:FPReplicationFollower [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/fpreplication/src/FPReplicationFollower.cpp:578:consume_messages(): consume_messages rval:0
May 02 11:56:00 SF-IMS[10482]: [10507] ADI:FPReplicationFollower [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/fpreplication/src/FPReplicationFollower.cpp:648:get_follower_event(): session seq_no is: 16 next_seq_no is: 16
May 02 11:56:00 SF-IMS[10482]: [10507] ADI:FPReplicationFollower [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/fpreplication/src/FPReplicationFollower.cpp:1225:process_message(): follower event is: CATCHUP_UPTODATE
May 02 11:56:00 SF-IMS[10482]: [10507] ADI:FPReplicationFollower [INFO] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/fpreplication/src/FPReplicationFollower.cpp:1213:process_catchup_uptodate_message(): received catchup entry up-to-date msg.
May 02 11:56:00 SF-IMS[10482]: [10507] ADI:FPReplicationFollower [INFO] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/fpreplication/src/FPReplicationFollower.cpp:977:process_buffered_messages(): begin to process 0 buffered messages
May 02 11:56:00 SF-IMS[10482]: [10507] ADI:FPReplicationFollower [INFO] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/fpreplication/src/FPReplicationFollower.cpp:1010:process_buffered_messages(): completely processed buffered broadcast messages.
May 02 11:56:00 SF-IMS[10482]: [10507] ADI:FPReplicationFollower [DEBUG] /var/tmp/build/workspace/IMS/IMS_6_7_0/FTD/src/libraries/fpreplication/src/FPReplicationFollower.cpp:576:consume_messages(): start consume_messages. Step 04: Terminate the process by sending ^C to your shell (CTRL +C on your keyboard)
Step 05: Enable adi process again
root@ftd01:/home/admin# pmtool enableById adiStep 06: Verify that adi is managed by process manager, up and running
root@ftd01:/home/admin# pmtool status | grep adi adi (normal) - Running 10710
Command: /ngfw/usr/local/sf/bin/adi
PID File: /ngfw/var/sf/run/adi.pid
Command: /ngfw/usr/local/sf/bin/beakerd --module-path=/ngfw/usr/local/sf/lib64 --log-file=/ngfw/var/log/beakerd.log --log-level=info --cfgdir=/ngfw/etc/sf/beakerd --pidfile=/ngfw/var/sf/run/beakerd.pid --enable-module=updater --enable-module=nikita --datadir=/ngfw/etc/sf/beakerd --listen=/ngfw/var/tmp/beaker_client.sock --listen=/ngfw/var/tmp/beaker_async_client.sock Summary
In this post we took a look at Firepowers pmtool utility and how we can use it control processes running on the system. You should now be able to verify the status of a process, restart it or disable it to perform additional system debugging. If you are interested in analyzing firepower logs checkout my post on pigtail, another useful troubleshooting utility for normalizing and analyzing firepower logfiles.
2 comments
Oliver, this is a great, awesome and very useful, blog
Thank you for posting this.
Enjoy reading your blog. Very useful and informative.