Viewing NDMP log information

Use the Storwize V7000 Unified CLI lsndmplog command to view information in the NDMP log. You can view the most recent 10 lines of the log, specify a number of lines to limit the display to the most recent entries, or save the entire log file as a local file on the active management node. You can also use the graphical user interface (GUI) to work with this function.

Use the Storwize V7000 Unified CLI lsndmplog command with the -g or --nodeGroup option to view all of the NDMP log information related to the specified file module group. In the following example, the file module group ndmpg1 is specified:

# lsndmplog -g NDMPG1

The most recent 10 lines of the NDMP log files for the file modules in the specified file module group are displayed by the CLI interface.

Note: You must specify either a file module group as in the above example, or a list of individual file modules using the -n option as in the example below, but not both in the same iteration of the lsndmplog command.

Use the Storwize V7000 Unified CLI lsndmplog command with the -n or --nodes option to view all of the NDMP log information related to the specified file module. In the following example, the file module mgmt001st001 is specified:The most recent 10 lines

# lsndmplog -n mgmt001st001

of the NDMP log file for the specified file module are displayed by the CLI interface.

Use the Storwize V7000 Unified CLI lsndmplog command with the -l or --lines option to view the most recent l lines of the NDMP log information related to the specified file module. In the following example, the file module mgmt001st001 and 25 lines are specified:

# lsndmplog -n mgmt001st001 -l 25

The most recent l lines of the NDMP log file for the specified file module is displayed by the CLI interface.

Use the Storwize V7000 Unified CLI lsndmplog command with the -o or --outputLogFilePath option to save the log file as a temporary file, as in the following example:

# lsndmplog -n mgmt001st001 -o /ibm/gpfs0/cifs_export/ndmplog.out

Note: The designated directory must be a current share or export on the file system. Attempting to save the log file to /root or any other non-exported directory will result in a message similar to the following one:

Error: the location chosen to save the NDMP log file must be an existing export.

While the Storwize V7000 Unified alert log viewed from the GUI is more helpful to most users, NDMP information is displayed in the NDMP log file in the format of the following sample.

The first column, XX:YY is for internal use only.
The second column is month and day in MM/DD format.
The third column is hour, minute, second, fraction of a second in hh:mm:ss:ffffff format.
The fourth column in decimal:hexadecimal format is the process ID of the process that generated the message.
- For many entries, this is the process ID of the NDMP backup or restore operation, and can be viewed with the -i or --session ID option of the lsndmpsession command.
The fifth column is program:subroutine:line, for internal use only.
The sixth and final column has multiple formats, depending on the type of entry:
- Some are text messages, some start with an event ID, and some display internal counters and their values.

IO:CN 10/06 19:34:47.546755 997774:258430f0       comm.c:ndmpRun:904 0001: Starting ndmpd listener on port 10000 of all IP address

The above message indicates that the NDMP data server is starting, and will be listening for control connections from a DMA of any IP address on port 10000

IO:CN 10/06 19:34:47.553348 997969:258430f0       comm.c:ndmpRun:980 0005: ndmpd started

The above message indicates that the NDMP data server has completed startup and is running.

DG:AS 10/06 19:34:55.563824 997979:8ffb4090       session_monitor.c:main:279 Cleaning up session 726147.da ...

The above message indicates that the NDMP data server is performing background maintenance to clean up after a previous NDMP session that did not complete normally. This would occur when the NDMP data server is restarted after an NDMP session failure.

IO:CN 10/06 19:43:55.816298 1035333:258430f0      data.c:ndmpdDataConnect_v4:902 1002: Data Server in CONNECTED state

The above message indicates that a control request has been received from a DMA, that the handshake process has completed, and that the NDMP data server is ready to communicate with the DMA.

IO:CN 10/06 19:43:55.890994 1035333:42b4c940      ndmp_backup.c:startBackup:443 7006: Level 0 backup of 
/ibm/gpfs0/shared/home/datafiles/test_dir3 started at Wed Oct  6 19:43:55 2010

The above message indicates that a full backup of the listed directory has started. Level 0 indicates a full backup.

DG:AS 10/06 19:43:55.909662 1035391:258430f0      log.c:logErrorInternal:642 CIL_event failed.

The above message indicates that an attempt by the NDMP data server to send an alert to the alert log has failed. CIL is an acronym for 'custom interface layer', which is an internal mechanism. One of several reasons that this error might display in the NDMP log might be that multiple identical Information messages have been sent. It is not necessary to call support based solely on the appearance of this message. Any actionable information is still displayed in the alert log.

IO:CN 10/06 19:44:42.216909 1035605:258430f0      data.c:ndmpdDataAbort:326 1010: Data Server received abort request
DG:AS 10/06 19:44:42.227389 1035605:420ac940      util.c:waitForData:1189 session aborted
IO:CN 10/06 19:44:42.227444 1035605:420ac940      util.c:waitForData:1190 1011: Data Server aborted

The above three messages were created by an NDMP stop session request from a DMA.

DG:AS 10/06 19:44:42.367566 1035605:416ab940    buffer.c:freeWriteQueueIndex:1472 numProcesses[4], perProcessBufferCount[41]

The above message is informational, showing the number of NDMP processes that are running (numProcesses[4]) and how many shared memory buffers are allocated (perProcessBufferCount[41]). This message appears when the number of sessions is reduced, because a backup or restore operation has either completed or been stopped manually.

IO:CN 10/06 19:46:19.538617 1035333:42b4c940     ndmp_backup.c:startBackup:652 7012: Level 0 backup of 
/ibm/gpfs0/shared/home/datafiles/test_dir3 finished at Wed Oct  6 19:46:19 2010.

The above message indicates that a full backup of the listed directory has completed.

IO:CN 10/06 19:46:19.545279 1035333:42b4c940      ndmp_backup.c:startBackup:662 7013: Total Bytes = 2048011272, 
Files:20 Directories:1 Throughput = 14250464.464822 bytes/sec.

The above message lists data transfer information for a completed backup: the number of bytes, files and directories that were restored, and throughput.

IO:CN 10/06 20:36:56.555597 1249104:43111940     ndmp_backup.c:startBackup:443 7006: Level 1 backup of 
/ibm/gpfs0/shared/home/datafiles/test_dir1 started at Wed Oct  6 20:36:56 2010.

The above message indicates that an incremental backup of the listed directory has started. Level 1 indicates an incremental backup.

DG:AS 10/06 20:35:23.057341 1240190:41f52940    util.c:waitForData:1211 select error: Success, abortFlag = 1
DG:AS 10/06 20:35:23.057417 1240190:41f52940    ndmp_brm_util.c:dataBufferWriteThread:633 Error sendfile
DG:AS 10/06 20:35:23.057440 1240190:41f52940    ndmp_brm_util.c:dataBufferWriteThread:684 rdErr:0 wrErr:1 skipping.
DG:AS 10/06 20:35:23.057780 1240190:41551940    ndmp_brm_util.c:flushDataCache:1080 rdErr:0 wrErr:1 skipping.
DG:AS 10/06 20:35:23.057833 1240190:41551940    ndmp_backup.c:startBackup:581 Error flushing data cache.
DG:AS 10/06 20:35:23.057857 1240190:41551940    buffer.c:freeWriteQueueIndex:1472 numProcesses[0], perProcessBufferCount[125]
DG:AS 10/06 20:35:23.064173 1242468:85f1b010    session_mgm_file.c:adminKillServer:472 Server 1240190 not terminated 6 seconds after SIGUSR1
DG:AS 10/06 20:35:29.065327 1242468:85f1b010    session_mgm_file.c:adminKillServer:472 Server 1240190 not terminated 7 seconds after SIGUSR1

The group of eight messages above appeared after an stopndmpsession command had been submitted. The exact number of each type of message varies. The first six messages in the group were generated by an NDMP backup session with a session ID of 1240190. The last two entries indicate that clean up operations for the NDMP session are still running. The NDMP data server is reporting the duration in seconds of the listed NDMP clean up session (Session ID 1240190). The following five messages were generated from a restore operation:

IO:CN 10/07 16:41:36.506940 1804292:5a8140f0    data.c:ndmpdDataConnect_v4:902 1002: Data Server in CONNECTED state

The above message indicates that a control request has been received from a DMA, that the handshake process has completed, and that the NDMP data server is ready to communicate with the DMA.

IO:CN 10/07 16:41:37.238097 1804292:42618940    ndmp_restore.c:ndmpRestore:327 8000: Restore 
     [/ibm/gpfs1/ndmp] started at Thu Oct  7 16:41:37 2010.

The above message indicates that a restore operation has started and lists the directory that is being restored.

IO:CN 10/07 16:41:41.684893 1804292:42618940     ndmp_restore.c:ndmpRestore:413 8003: Restore 
     processed bytes = 1536010248

The above message lists the total number of bytes that were processed during the restore operation.

IO:CN 10/07 16:41:41.691832 1804292:42618940     ndmp_restore.c:ndmpRestore:426 8005: Restore 
     [/ibm/gpfs1/ndmp] completed at Thu Oct  7 16:41:41 2010.

The above message indicates when the restore of the listed directory completed.

IO:CN 10/07 16:41:41.697577 1804292:42618940     ndmp_restore.c:ndmpRestore:436 Total Bytes = 1536010248, 
     Files:15 Directories:4 Throughput = 344438002.021766 bytes/sec.

The above message lists data transfer information for a completed restore: the number of bytes, files and directories that were restored, and throughput.

DG:AS 12/14 14:27:20.896993 1223253:e8c0e010          session_mgm_file.c:adminReleaseSlot:568 Invalid file handle:
/var/ndmp/session//1216740.dat:No such file or directory
This is a harmless condition.  The session_monitor runs in a loop checking the session info files.  In this case, 
session_monitor noticed that there is a session_info file and checks to see if the session is still there.  But between 
this, the session is exiting and has already cleaned up the session info file.  So by the time the session_monitor tries 
to read the session info file to perform clean up, the session info file is already gone.

The above message an informational message stating that an NDMP session has cleaned up its own temporary session file before the session_monitor daemon was able to clean up the temporary session file for that session. This message does not indicate an error; no action is required.

Note: Display output wraps differently, depending on the user interface window.

Note: If NDMP has recently been activated, it is normal to see several warning messages of type AK016CW with a statement that the NDMP daemon and/or session_monitor daemon is not running.

GUI navigation

To work with this function in the management GUI, log on to the GUI and select Files > Services > Backup.