Cisco NAC Manager HA log files

The NAC Manager documentation provides a number of logs that can be viewed to troubleshoot various issues. The only problem is that when a problem occurs it would be really nice to have a reference showing what good log output looks like. That's what I'd like to share here. Hopefully this will help someone troubleshooting an issue.

The log files below show the log files on a standby NAM when it becomes active
/perfigo/control/tomcat/logs/localhost_log..txt
2008-11-19 14:22:58 StandardHost[localhost]: Removing web application at context path /admin
2008-11-19 14:22:58 StandardHost[localhost]: Removing web application at context path
2008-11-19 14:23:03 WebappLoader[/admin]: Deploying class repositories to work directory /perfigo/control/tomcat/work/Standalone/localhost/admin
2008-11-19 14:23:03 WebappLoader[/admin]: Deploy JAR /WEB-INF/lib/jsf_hack_tld.jar to /perfigo/control/tomcat/webapps/admin/WEB-INF/lib/jsf_hack_tld.jar
2008-11-19 14:23:04 ContextConfig[/admin]: Configured an authenticator for method NONE
2008-11-19 14:23:04 PersistentManager[/admin]: Seeding random number generator class java.security.SecureRandom
2008-11-19 14:23:04 PersistentManager[/admin]: Seeding of random number generator has been completed
2008-11-19 14:23:04 PersistentManager[/admin]: No Store configured, persistence disabled
2008-11-19 14:23:22 StandardWrapper[/admin:default]: Loading container servlet default
2008-11-19 14:23:22 StandardWrapper[/admin:invoker]: Loading container servlet invoker
2008-11-19 14:23:22 HostConfig[localhost]: Deploying web application directory ROOT
2008-11-19 14:23:22 StandardHost[localhost]: Installing web application at context path from URL file:/perfigo/control/tomcat/normal-webapps/ROOT
2008-11-19 14:23:22 WebappLoader[]: Deploying class repositories to work directory /perfigo/control/tomcat/work/Standalone/localhost/_
2008-11-19 14:23:22 StandardManager[]: Seeding random number generator class java.security.SecureRandom
2008-11-19 14:23:22 StandardManager[]: Seeding of random number generator has been completed
2008-11-19 14:23:23 StandardWrapper[:default]: Loading container servlet default
2008-11-19 14:23:23 StandardWrapper[:invoker]: Loading container servlet invoker
2008-11-19 14:23:23 HostConfig[localhost]: Deploying web application directory upload
2008-11-19 14:23:23 StandardHost[localhost]: Installing web application at context path /upload from URL file:/perfigo/control/tomcat/normal-webapps/upload
2008-11-19 14:23:23 WebappLoader[/upload]: Deploying class repositories to work directory /perfigo/control/tomcat/work/Standalone/localhost/upload
2008-11-19 14:23:23 StandardManager[/upload]: Seeding random number generator class java.security.SecureRandom
2008-11-19 14:23:23 StandardManager[/upload]: Seeding of random number generator has been completed
2008-11-19 14:23:23 StandardWrapper[/upload:default]: Loading container servlet default
2008-11-19 14:23:23 StandardWrapper[/upload:invoker]: Loading container servlet invoker
2008-11-19 14:23:23 HostConfig[localhost]: Deploying web application directory wlan
2008-11-19 14:23:23 StandardHost[localhost]: Installing web application at context path /wlan from URL file:/perfigo/control/tomcat/normal-webapps/wlan
2008-11-19 14:23:23 WebappLoader[/wlan]: Deploying class repositories to work directory /perfigo/control/tomcat/work/Standalone/localhost/wlan
2008-11-19 14:23:23 ContextConfig[/wlan]: Configured an authenticator for method NONE
2008-11-19 14:23:23 StandardManager[/wlan]: Seeding random number generator class java.security.SecureRandom
2008-11-19 14:23:23 StandardManager[/wlan]: Seeding of random number generator has been completed
2008-11-19 14:23:23 StandardWrapper[/wlan:default]: Loading container servlet default
2008-11-19 14:23:23 StandardWrapper[/wlan:invoker]: Loading container servlet invoker
2008-11-19 14:23:23 HostConfig[localhost]: Deploying web application directory packages
2008-11-19 14:23:23 StandardHost[localhost]: Installing web application at context path /packages from URL file:/perfigo/control/tomcat/normal-webapps/packages
2008-11-19 14:23:23 WebappLoader[/packages]: Deploying class repositories to work directory /perfigo/control/tomcat/work/Standalone/localhost/packages
2008-11-19 14:23:23 StandardManager[/packages]: Seeding random number generator class java.security.SecureRandom
2008-11-19 14:23:23 StandardManager[/packages]: Seeding of random number generator has been completed
2008-11-19 14:23:24 StandardWrapper[/packages:default]: Loading container servlet default
2008-11-19 14:23:24 StandardWrapper[/packages:invoker]: Loading container servlet invoker
2008-11-19 14:23:24 HostConfig[localhost]: Deploying web application directory download
2008-11-19 14:23:24 StandardHost[localhost]: Installing web application at context path /download from URL file:/perfigo/control/tomcat/normal-webapps/download
2008-11-19 14:23:24 WebappLoader[/download]: Deploying class repositories to work directory /perfigo/control/tomcat/work/Standalone/localhost/download
2008-11-19 14:23:24 StandardManager[/download]: Seeding random number generator class java.security.SecureRandom
2008-11-19 14:23:24 StandardManager[/download]: Seeding of random number generator has been completed
2008-11-19 14:23:24 StandardWrapper[/download:default]: Loading container servlet default
2008-11-19 14:23:24 StandardWrapper[/download:invoker]: Loading container servlet invoker

/var/log/ha-log
heartbeat: 2008/11/19_14:22:58 info: Received shutdown notice from 'camanager1'.
heartbeat: 2008/11/19_14:22:58 info: Resources being acquired from camanager1.
heartbeat: 2008/11/19_14:22:58 info: acquire all HA resources (standby).
heartbeat: 2008/11/19_14:22:58 info: No local resources [/usr/lib64/heartbeat/ResourceManager listkeys camanager2] to acquire.
heartbeat: 2008/11/19_14:22:58 info: Acquiring resource group: camanager1 x.x.x.x controlsmart
heartbeat: 2008/11/19_14:22:58 info: Running /etc/ha.d/resource.d/IPaddr x.x.x.x start
heartbeat: 2008/11/19_14:22:58 info: /sbin/ifconfig eth0:0 x.x.x.x netmask 255.255.255.0 broadcast 172.31.31.255
heartbeat: 2008/11/19_14:22:58 info: Sending Gratuitous Arp for x.x.x.x on eth0:0 [eth0]
heartbeat: 2008/11/19_14:22:58 /usr/lib64/heartbeat/send_arp -i 1010 -r 5 -p /var/lib/heartbeat/rsctmp/send_arp/send_arp-x.x.x.x eth0 x.x.x.x auto x.x.x.x ffffffffffff
heartbeat: 2008/11/19_14:22:58 info: Running /perfigo/control/bin/controlsmart start
heartbeat: 2008/11/19_14:23:02 info: all HA resource acquisition completed (standby).
heartbeat: 2008/11/19_14:23:02 info: Standby resource acquisition done [all].
heartbeat: 2008/11/19_14:23:02 info: Running /etc/ha.d/rc.d/status status
heartbeat: 2008/11/19_14:23:04 info: Taking over resource group x.x.x.x
heartbeat: 2008/11/19_14:23:04 info: Acquiring resource group: camanager1 x.x.x.x controlsmart
heartbeat: 2008/11/19_14:23:04 info: Running /perfigo/control/bin/controlsmart start
heartbeat: 2008/11/19_14:23:04 info: /usr/lib64/heartbeat/mach_down: nice_failback: foreign resources acquired
heartbeat: 2008/11/19_14:23:04 info: mach_down takeover complete.
heartbeat: 2008/11/19_14:23:04 info: mach_down takeover complete for node camanager1.
heartbeat: 2008/11/19_14:23:14 WARN: node camanager1: is dead
heartbeat: 2008/11/19_14:23:14 info: Dead node camanager1 gave up resources.
heartbeat: 2008/11/19_14:23:14 info: Link camanager1:eth1 dead.

These logs show the story when a NAM starts as the active NAM and then "service perfigo stop" is entered to turn off the NAC service
/perfigo/control/tomcat/logs/localhost_log..txt
2008-11-19 14:22:55 StandardHost[localhost]: Removing web application at context path /admin
2008-11-19 14:22:55 StandardHost[localhost]: Removing web application at context path /upload
2008-11-19 14:22:55 StandardHost[localhost]: Removing web application at context path /download
2008-11-19 14:22:55 StandardHost[localhost]: Removing web application at context path /packages
2008-11-19 14:22:55 StandardHost[localhost]: Removing web application at context path /wlan
2008-11-19 14:22:55 StandardHost[localhost]: Removing web application at context path

/var/log/ha-debug
heartbeat: 2008/11/19_14:22:54 info: Heartbeat shutdown in progress. (4516)
heartbeat: 2008/11/19_14:22:54 info: Giving up all HA resources.
heartbeat: 2008/11/19_14:22:54 info: Releasing resource group: camanager1 x.x.x.x controlsmart
heartbeat: 2008/11/19_14:22:54 info: Running /perfigo/control/bin/controlsmart stop
heartbeat: 2008/11/19_14:22:58 info: Running /etc/ha.d/resource.d/IPaddr x.x.x.x stop
heartbeat: 2008/11/19_14:22:58 info: /sbin/route -n del -host x.x.x.x
heartbeat: 2008/11/19_14:22:58 info: /sbin/ifconfig eth0:0 down
heartbeat: 2008/11/19_14:22:58 info: IP Address x.x.x.x released
heartbeat: 2008/11/19_14:22:58 info: All HA resources relinquished.
heartbeat: 2008/11/19_14:22:59 info: killing HBREAD process 4521 with signal 15
heartbeat: 2008/11/19_14:22:59 info: killing HBFIFO process 4519 with signal 15
heartbeat: 2008/11/19_14:22:59 info: killing HBWRITE process 4520 with signal 15
heartbeat: 2008/11/19_14:22:59 info: Core process 4519 exited. 3 remaining
heartbeat: 2008/11/19_14:22:59 info: Core process 4520 exited. 2 remaining
heartbeat: 2008/11/19_14:22:59 info: Core process 4521 exited. 1 remaining
heartbeat: 2008/11/19_14:22:59 info: Heartbeat shutdown complete.

This show the status after "service perfigo start" is entered with another NAM active
[root@camanager1 logs]# service perfigo start
Starting High-Availability services:
[ OK ]
Please wait while bringing up service IP.
Heartbeat service is running.
Service IP is up on the peer node.
Stopping postgresql service: [ OK ]
Starting postgresql service: [ OK ]
DROP DATABASE
CREATE DATABASE
DROP DATABASE
CREATE DATABASE
Database synced
[root@camanager1 logs]#

/perfigo/control/tomcat/logs/localhost_log..txt
2008-11-19 14:30:14 WebappLoader[/admin]: Deploying class repositories to work directory /perfigo/control/tomcat/work/Standalone/localhost/admin
2008-11-19 14:30:14 WebappLoader[/admin]: Deploy JAR /WEB-INF/lib/jsf_hack_tld.jar to /perfigo/control/tomcat/webapps/admin/WEB-INF/lib/jsf_hack_tld.jar
2008-11-19 14:30:14 ContextConfig[/admin]: Configured an authenticator for method NONE
2008-11-19 14:30:14 PersistentManager[/admin]: Seeding random number generator class java.security.SecureRandom
2008-11-19 14:30:14 PersistentManager[/admin]: Seeding of random number generator has been completed
2008-11-19 14:30:14 PersistentManager[/admin]: No Store configured, persistence disabled
2008-11-19 14:30:15 StandardWrapper[/admin:default]: Loading container servlet default
2008-11-19 14:30:15 StandardWrapper[/admin:invoker]: Loading container servlet invoker
2008-11-19 14:30:15 HostConfig[localhost]: Deploying web application directory ROOT
2008-11-19 14:30:15 StandardHost[localhost]: Installing web application at context path from URL file:/perfigo/control/tomcat/admin-webapps/ROOT
2008-11-19 14:30:15 WebappLoader[]: Deploying class repositories to work directory /perfigo/control/tomcat/work/Standalone/localhost/_
2008-11-19 14:30:15 StandardManager[]: Seeding random number generator class java.security.SecureRandom
2008-11-19 14:30:15 StandardManager[]: Seeding of random number generator has been completed
2008-11-19 14:30:16 StandardWrapper[:default]: Loading container servlet default
2008-11-19 14:30:16 StandardWrapper[:invoker]: Loading container servlet invoker

/var/log/ha-log
heartbeat: 2008/11/19_14:27:25 info: **************************
heartbeat: 2008/11/19_14:27:25 info: Configuration validated. Starting heartbeat 1.2.5
heartbeat: 2008/11/19_14:27:25 info: heartbeat: version 1.2.5
heartbeat: 2008/11/19_14:27:26 info: Heartbeat generation: 44
heartbeat: 2008/11/19_14:27:26 info: ucast: write socket priority set to IPTOS_LOWDELAY on eth1
heartbeat: 2008/11/19_14:27:26 info: ucast: trying to bind: eth1

heartbeat: 2008/11/19_14:27:26 info: ucast: bound send socket to device: eth1
heartbeat: 2008/11/19_14:27:26 info: ucast: try binding receive socket to device: eth1
heartbeat: 2008/11/19_14:27:26 info: ucast: could bind receive socket to device: eth1:fe00a8c0.
heartbeat: 2008/11/19_14:27:26 info: ucast: started on port 694 interface eth1 to 192.168.0.253
heartbeat: 2008/11/19_14:27:26 notice: Using watchdog device: /dev/watchdog
heartbeat: 2008/11/19_14:27:26 info: pid 19899 locked in memory.
heartbeat: 2008/11/19_14:27:26 info: Local status now set to: 'up'
heartbeat: 2008/11/19_14:27:27 info: pid 19902 locked in memory.
heartbeat: 2008/11/19_14:27:27 info: pid 19903 locked in memory.
heartbeat: 2008/11/19_14:27:27 info: pid 19904 locked in memory.
heartbeat: 2008/11/19_14:27:27 info: Link camanager2:eth1 up.
heartbeat: 2008/11/19_14:27:27 info: Status update for node camanager2: status active
heartbeat: 2008/11/19_14:27:27 info: Local status now set to: 'active'
heartbeat: 2008/11/19_14:27:27 info: remote resource transition completed.
heartbeat: 2008/11/19_14:27:27 info: remote resource transition completed.
heartbeat: 2008/11/19_14:27:27 info: Local Resource acquisition completed. (none)
heartbeat: 2008/11/19_14:27:27 info: Initial resource acquisition complete (T_RESOURCES(them))
heartbeat: 2008/11/19_14:27:27 info: Running /etc/ha.d/rc.d/status status