Analyzing the log files

Edit online

If you receive errors while you run the ksysmgr command, you can analyze the log files to diagnose the issue. Determine the software component that is causing the problem by analyzing the log files. You can find the ksysmgr command log files in the /var/ksys/log/ directory.

After a log file such as host_monitor.log, host_monitor_crit.log, and host_monitor_hvncp.log reaches a maximum size of 20 MB, the existing log file is backed up and a new log file is created. By default, network logging is not enabled. The spooling file that has the highest number in the file name will be the oldest log file. By default, three spooling files are created for log collection. You can configure the number of spooling files by using the ksysmgr command. The maximum value is 10 spooling files.

When you run the ksysmgr command, the following types of log files are created:

ksysmgr.oplog: Keeps a rolling record of all the ksysmgr operations that you ran for a specific period. All the commands that you entered are logged in this log file along with the date, time, and the transaction ID.
ksysmgr.log: Contains the detailed processing information about each function when you run a ksysmgr command.
Note: The ksysmgr.log file contains the detailed processing information only when you specify the -l max flag when you run the ksysmgr command.
ksys_srdf.log: Contains the detailed processing information about all the EMC SRDF storage-specific functions along with the date and time.
ksys_svc.log: Contains the detailed processing information about all the SVC Storwize storage-specific functions along with the date and time.
ksys_ccl.log: Contains the detailed processing information about all the Hitachi storage-specific functions along with the date and time.
ksys_ds8k.log: Contains the detailed processing information about all the DS8000 series storage-specific functions along with the date and time.
ksys_unity.log: Contains the detailed processing information about all the EMC Unity storage-specific functions along with the date and time.

Trace files contain the details about processes that are running as part of the operations performed by the KSYS node. If you cannot identify the cause of the error by analyzing the log files, use the trace files for problem determination. Run the following command to convert trace files to a report:

ksysmgr trace log type=ksys|fde|fdelong|krest|krestlong|user|ALL

If large number of virtual machines are included in the ksysmgr-related operations, you can increase the size of the trace files to accommodate more log information. You can increase the size of trace file by using the /var/ct/cfg file as follows:

/var/ct/cfg
# cat trace.conf
IBM.VMR:
    pat        = /var/ct/.*/log/mc/IBM.VMR/.*
    spooling   = OFF
    pages      = 4
    dest       = /tmp/ksys/rm/
    #size      = 8192000
    size       = 11534336

This example changes the size of trace files from 8 MB to 11 MB.

Example for the ksysmgr.oplog file and the ksysmgr.log file

This example shows samples for the ksysmgr.oplog file and the ksysmgr.log files.

For instance, you can run the following commands to add a KSYS cluster called test_cluster and then, you can run the commands to verify and sync the cluster:


ksysmgr add cluster test_cluster ksysnodes=xxx.xx.xx.ibm.com // Creates a cluster called test_cluster.
ksysmgr verify ksyscluster test_cluster                      // Verifies the cluster.
ksysmgr -l max sync ksyscluster test cluster                 // To Sync the cluster.
                                                             // However, the cluster name is misspelled. 
                                                             //       The output displays error.
ksysmgr -l max sync ksyscluster test_cluster                 // Syncs the cluster. 
                                                             //       The output indicates success.

In this scenario, the contents of the ksysmgr.oplog file might be similar to the following sample:

8/3/2106 23:50:12   15401408    ksysmgr add cluster test_cluster ksysnodes=xxx.xx.xx.ibm.com
8/3/2106 23:54:35   15401222    ksysmgr verify ksyscluster test_cluster
8/3/2106 23:54:59   15401238    ksysmgr -l max sync ksyscluster test cluster
8/3/2106 23:55:5    10551612    ksysmgr -l max sync ksyscluster test_cluster

The contents of the ksysmgr.log file might be similar to the following sample. Because the -l max flag was not specified in the first two commands, the details for those commands are not logged in the ksysmgr.log file.

ksysmgr_setenv()[134]:  ENTERING with (ksysmgr_TRANSACTION_ID, 15401238, 809)
main()[811]:    Setting ksysmgr_TRANSACTION=15401238 in the environment.
main()[855]:    Processing the action input, "sync".
expand_action()[430]:   ENTERING with (sync, ksysmgr -l max sync ksyscluster test cluster)
expand_action()[472]:   Converted user action "sync" to "sync" using the "exact match" alias "sync".
main()[884]:    The fully expanded action is "sync".
main()[892]:    Processing the class input, "ksyscluster".
expand_class()[161]:    ENTERING with (ksyscluster, ksysmgr -l max sync ksyscluster test cluster)
expand_class()[224]:    Converted user class "ksyscluster" to "ksyscluster" using the "exact match" 
                         alias "ksyscluster".
expand_class()[249]:    Expanded class: "ksyscluster")
main()[925]:    The fully expanded class is "ksyscluster".
main()[932]:    Processing the "object" input, "test".
main()[944]:    Processing ATTR=VALUE input, "cluster".
main()[954]:    Remaining space for attributes is 3001 bytes.
sync_ksyscluster()[541]:    ENTERING
sync_ksyscluster()[557]:    START PROCESSING INPUTS FROM USER
-------------------------------------------------- 
ksysmgr_setenv()[134]:  ENTERING with (ksysmgr_TRANSACTION_ID, 10551612, 809)
main()[811]:    Setting ksysmgr_TRANSACTION=10551612 in the environment.
main()[855]:    Processing the action input, "sync".
expand_action()[430]:   ENTERING with (sync, ksysmgr -l max sync ksyscluster test_cluster)
expand_action()[472]:   Converted user action "sync" to "sync" using the "exact match" alias "sync".
main()[884]:    The fully expanded action is "sync".
main()[892]:    Processing the class input, "ksyscluster".
expand_class()[161]:    ENTERING with (ksyscluster, ksysmgr -l max sync ksyscluster test_cluster)
expand_class()[224]:    Converted user class "ksyscluster" to "ksyscluster" using the "exact match" 
                        alias "ksyscluster".
expand_class()[249]:    Expanded class: "ksyscluster")
main()[925]:    The fully expanded class is "ksyscluster".
main()[932]:    Processing the "object" input, "test_cluster".
sync_ksyscluster()[541]:    ENTERING
sync_ksyscluster()[557]:    START PROCESSING INPUTS FROM USER
sync_ksyscluster()[590]:    DONE PROCESSING INPUTS FROM USER
runSystemCommand()[198]:    RUNNING COMMAND:/usr/bin/grep -q -F $(/usr/bin/hostname) 
                            /var/ct/cfg/ctrmc.acls
runSystemCommand()[198]:    RUNNING COMMAND:/usr/sbin/rsct/bin/mkrpdomain test_cluster 
                            $(/usr/bin/hostname) > /dev/null 2>&1;
runSystemCommand()[198]:    RUNNING COMMAND:/usr/sbin/rsct/bin/startrpdomain test_cluster> 
                            /dev/null 2>&1;
runSystemCommand()[170]:    ERROR: 1
runSystemCommand()[170]:    ERROR: 1
runSystemCommand()[170]:    ERROR: 1
runSystemCommand()[198]:    RUNNING COMMAND:/usr/bin/stopsrc -s IBM.VMR > /dev/null 2>&1; 
                            /usr/bin/sleep 5; 
                            /usr/sbin/rsct/bin/rmcctrl -z > /dev/null 2>&1; 
                            /usr/sbin/rsct/bin/rmcctrl -A > /dev/null 2>&1; 
                            /usr/bin/startsrc -s IBM.VMR > /dev/null 2>&1; 
                            /usr/bin/sleep 5; /usr/sbin/rsct/bin/rmcctrl -A > /dev/null 2>&1;
runSystemCommand()[198]:    RUNNING COMMAND:/usr/bin/lssrc -g rsct_rm | /usr/bin/grep IBM.VMR | 
                            /usr/bin/awk '{print $4}' | /usr/bin/grep -q -F -- 'active';
sync_ksyscluster()[663]:    EXITING SUCCESSFULLY

Example for the ksys_srdf.log file

This example shows a sample of the ksys_srdf.log file:

For instance, you initiate a planned recovery from the active site to the backup site, and problems occur during the storage reverse replication. The output of the command displays the error. However, if you want to know the exact step where this problem occurred, you can review the ksys_srdf.log file as follows:

...
Wed Aug 17 04:45:03 CDT 2016 reverse_emc_srdf_cg: srdf_cg_query : Successfully Processed 
                             /var/ksys/log/data-0-1Amy3-839-1471427099.xml
Wed Aug 17 04:45:03 CDT 2016 reverse_emc_srdf_cg: 119 : CG: VMRDG_Cheese50_vmdr_Site1 in Asynchronous
Wed Aug 17 04:45:03 CDT 2016 reverse_emc_srdf_cg: 136 : Info: CG VMRDG_Cheese50_vmdr_Site1 in PLAN
Wed Aug 17 04:45:03 CDT 2016 reverse_emc_srdf_cg: 150 : SID:196800573 : SOURCE for 
                             VMRDG_Cheese50_vmdr_Site1
Wed Aug 17 04:45:03 CDT 2016 reverse_emc_srdf_cg: 161 : Info: CG VMRDG_Cheese50_vmdr_Site1 in 
                             State:Consistent Type:RDF2
Wed Aug 17 04:45:03 CDT 2016 reverse_emc_srdf_cg: CG_DisableConsistency : CG:VMRDG_Cheese50_vmdr_Site1 
                             Start
Wed Aug 17 04:45:03 CDT 2016 reverse_emc_srdf_cg: srdf_cg_cmd_exec : Command Executing : 11
Wed Aug 17 04:45:04 CDT 2016 reverse_emc_srdf_cg: log_srdf_msg : Error:
                             All the devices in the SRDF/A session must be managed together 
                             when the devices are in async mode
Wed Aug 17 04:45:04 CDT 2016 reverse_emc_srdf_cg: CG_DisableConsistency : CG: VMRDG_Cheese50_vmdr_Site1 
                             disable consistency failed:1
Wed Aug 17 04:45:04 CDT 2016 reverse_emc_srdf_cg: CG_EnableAcpMode : CG:VMRDG_Cheese50_vmdr_Site1 Start
Wed Aug 17 04:45:04 CDT 2016 reverse_emc_srdf_cg: srdf_cg_cmd_exec : Command Executing : 13
Wed Aug 17 04:45:05 CDT 2016 reverse_emc_srdf_cg: CG_EnableAcpMode : Failed with status 1
Wed Aug 17 04:45:05 CDT 2016 reverse_emc_srdf_cg: log_srdf_msg : Error:
An RDF Set 'ACp Disk Mode ON' operation execution is in
progress for composite group 'VMRDG_Cheese50_vmdr_Site1'. Please wait...
...

In this example, it is clear that the issue occurred during the CG_DisableConsistency phase.

Collecting log files for VM Recovery Manager DR

You can collect the log files of the KSYS subsystem by running the snap vmsnap command on the KSYS node. You can use these log files to debug issues that might occur while performing KSYS operations. To run the snap vmsnap command successfully, the /tmp folder must have 2 GB or more space. The log data is recorded in the /tmp/ibmsupt/vmsnap/ksys.pax.Z file.

Note:

For the cluster type DR, the host monitor and virtual machine logs will not be collected.
To collect logs of host monitor and VM monitor, you must log in to the respective VIOS and VM.
- To collect log data from VM monitor, run the following command in the VM:
```
ksysvmmgr snap
```
- To collect log data from host monitor, run the following command in the VIOS:
- ```
snap -a
```

To collect log files for the KSYS subsystem, run the following command:

snap vmsnap

An output similar to the following example is displayed:

********Checking and initializing directory structure
Directory /tmp/ibmsupt/vmsnap already exists... skipping
Directory /tmp/ibmsupt/testcase already exists... skipping
Directory /tmp/ibmsupt/other already exists... skipping
********Finished setting up directory /tmp/ibmsupt

Checking Space requirement for vmsnap

Checking space requirements for my product...Checking for enough free space in filesystem... done.

Gathering vmsnap data

Gathering VMRM product information...

Clearing the /tmp/ibmsupt/vmsnap of redundant files and directories...

Gathering VM/HM logs...

Collecting the VM logs for HG=0 (0 = ALL HGs)...
Collecting the HM logs for HG=0 (0 = ALL HGs)...
Successfully started VM/HM log collection...

To check the status of VM/HM log collection, please run 'ksysmgr query system status monitor=yes'

Gathering RM traces and registry...

...................
Cleaning old temporary directory at
Log directory set to /tmp/ibmsupt/vmsnap/tmpstage.12124544
tar file set to /tmp/ibmsupt/vmsnap/tmpstage.12124544/ctsnap.ksys216.1106084226.tar
Gathering information......
Running gcore/gencore for active daemons...
............................
Completed running gcore/gencore for active daemons.
Preparing /var/ct on /tmp/ibmsupt/vmsnap/tmpstage.12124544/trclog//var/ct/

Gathering information......
..................................................................................................Gathering trace spool files as follows:
lstrsp --node_name ksys216 --previous 1 --tar ./tmp/ibmsupt/vmsnap/tmpstage.12124544/ctsnap_out/TRACE_SPOOL.tar --no_usage --tar_ticks
Done gathering trace spool files

Starting tar/compress process......
copying files from /tmp/ibmsupt/vmsnap/tmpstage.12124544 to /tmp/ibmsupt/vmsnap
deleting temporary directory /tmp/ibmsupt/vmsnap/tmpstage.12124544
*******done*******
Successfully gathered RM traces and registry data...

Gathering storage and UIagent related data...

Successfully gathered storage and UIagent related data...

Gatheing KSYS resource attributes...

Successfully gathered KSYS resource attributes...

Gatheing KSYS class attributes...

Successfully gathered KSYS classes attributes...

Gathering General System information...

Successfully gathered general system information...

Removing existing redundant files if present in /tmp/ibmsupt/vmsnap.
Removing the extraneous files copied and compressed in the snap file ksys.pax.Z

VMRM snap data can be found in the file:/tmp/ibmsupt/vmsnap/ksys.pax.Z
VM and HM logs can be found in their corresponding VM's and HM's log location.
VM log location:/var/ksys/log/snap   HM log location:/tmp/ibmsupt/snap