Hi Pro's
I use : TSM 6.3.4, Win2012, Netapp Ontap 8.1.4P2 7-mode, FC attached tape drives configured with datamovers and virtualvolumes.
I have some problems with my NDMP backups. I run NDMP backups frequently on differnt size of virtualvolumes. But I have a some volumes that I always have problem to dump. I can't find what the problem is. Below you can see two of the ndmpd errors from the netapp ndmpd log. The first gets BAD_MEDIA, and the other one gets a "requesting ABORT"
First dump that Went wrong today:
00000052.0005428f 05c38cce Wed Oct 29 2014 11:17:01 +01:00 [kern_ndmpd:info:1951] [16184] INFO: MOVER: query 3434610688 bytes, 52408 records 36.63KB/s (avg 65.69KB/s) (0) rst5a
00000052.00054294 05c39755 Wed Oct 29 2014 11:21:30 +01:00 [kern_ndmpd:info:1951] [16184] INFO: DATA: query 3443948544 bytes in DATA_OP_BACKUP (0)
00000052.00054295 05c397e9 Wed Oct 29 2014 11:21:45 +01:00 [kern_ndmpd:info:1951] [15229] INFO: DATA: query 2142091343872 bytes in DATA_OP_BACKUP (0)
00000052.00054296 05c397e9 Wed Oct 29 2014 11:21:45 +01:00 [kern_ndmpd:info:1951] [15229] INFO: MOVER: query 2142091280384 bytes, 32685719 records 51.61KB/s (avg 21.33MB/s) (0) rst4a
00000052.00054297 05c39850 Wed Oct 29 2014 11:21:55 +01:00 [kern_ndmpd:info:1951] [15229] INFO: DATA notification state 5 (SESS_STATE: HALTING) event 6 (EVENT: BAD_MEDIA)
00000052.00054298 05c39850 Wed Oct 29 2014 11:21:55 +01:00 [kern_ndmpd:info:1951] [15229] ERROR: DATA: Backup terminated: EVENT: BAD_MEDIA (for /vol/vol2/.snapshot/2014_q3/groups/A/JKP)
00000052.00054299 05c39850 Wed Oct 29 2014 11:21:55 +01:00 [kern_ndmpd:info:1951] [15229] INFO: MOVER: signal HALT CLOSE (abort)
00000052.0005429a 05c39850 Wed Oct 29 2014 11:21:55 +01:00 [kern_ndmpd:info:1951] [15229] INFO: MOVER halt on 'closed': MOVER operation successful (CLOSE)
00000052.0005429b 05c39850 Wed Oct 29 2014 11:21:55 +01:00 [kern_ndmpd:info:1951] [15229] INFO: DATA: query 2142091343872 bytes in DATA_OP_HALT_UNKNOWN (0)
00000052.0005429c 05c39850 Wed Oct 29 2014 11:21:55 +01:00 [kern_ndmpd:info:1951] [15229] INFO: MOVER: query 2142091280384 bytes, 32685719 records (avg 21.33MB/s) (0) rst4a
00000052.0005429f 05c39884 Wed Oct 29 2014 11:22:00 +01:00 [kern_ndmpd:info:1951] [15229] INFO: MOVER: received ABORT command
00000052.000542a0 05c39884 Wed Oct 29 2014 11:22:00 +01:00 [kern_ndmpd:info:1951] [15229] ERROR: MOVER: Rejecting ABORT request for MOVER_OP_HALT_CLOSE state.
00000052.000542a1 05c39884 Wed Oct 29 2014 11:22:01 +01:00 [kern_ndmpd:info:1951] [15229] INFO: DATA: received ABORT command (-0:00:01)
00000052.000542a2 05c39884 Wed Oct 29 2014 11:22:01 +01:00 [kern_ndmpd:info:1951] [15229] ERROR: DATA: Rejecting ABORT request for DATA_OP_HALT_UNKNOWN state. (-0:00:01)
00000052.000542a3 05c39884 Wed Oct 29 2014 11:22:01 +01:00 [kern_ndmpd:info:1951] [15229] INFO: DATA: received STOP command (-0:00:01)
00000052.000542a4 05c39884 Wed Oct 29 2014 11:22:01 +01:00 [kern_ndmpd:info:1951] [15229] INFO: SCSI: TAPE MTIO REWIND 1 rst4a (-0:00:01)
00000052.000542a5 05c398f3 Wed Oct 29 2014 11:22:12 +01:00 [kern_ndmpd:info:1951] [16184] INFO: MOVER: query 3445620736 bytes, 52576 records 34.57KB/s (avg 65.51KB/s) (0) rst5a (-0:00:01)
00000052.000542a7 05c39987 Wed Oct 29 2014 11:22:26 +01:00 [kern_ndmpd:info:1951] [15229] INFO: SCSI: TAPE MTIO BSF 1 rst4a
00000052.000542a8 05c39987 Wed Oct 29 2014 11:22:26 +01:00 [kern_ndmpd:info:1951] [15229] INFO: SCSI: TAPE MTIO UNLOAD 1 rst4a
00000052.000542a9 05c39988 Wed Oct 29 2014 11:22:27 +01:00 [kern_ndmpd:info:1951] [15229] NOTICE: SCSI: UNLOAD: rst4a REWINDING
00000052.000542aa 05c39988 Wed Oct 29 2014 11:22:27 +01:00 [kern_ndmpd:info:1951] [15229] NOTICE: SCSI: UNLOAD: rst4a UNLOADING...
00000052.000542ab 05c39aad Wed Oct 29 2014 11:22:56 +01:00 [kern_ndmpd:info:1951] [15290] INFO: TEST READY: STD 0x70 (Current) sense 2 (NOT READY) (len 64) {rst0a} (-0:00:01)
00000052.000542ac 05c39aad Wed Oct 29 2014 11:22:56 +01:00 [kern_ndmpd:info:1951] [15290] INFO: TEST READY: ASC/Q 0401 [LUN Not Ready, Calibration in Process] (-0:00:01)
The second error on another NDMP dump that got wrong later today:
00000052.0005446c 05c58844 Wed Oct 29 2014 14:53:33 +01:00 [kern_ndmpd:info:1951] [16184] INFO: DATA: query 3860307968 bytes in DATA_OP_BACKUP (0) (-0:00:01)
00000052.0005446d 05c589de Wed Oct 29 2014 14:54:14 +01:00 [kern_ndmpd:info:1951] [16184] INFO: MOVER: query 3861774336 bytes, 58926 records 25.07KB/s (avg 58.84KB/s) (0) rst5a (-0:00:01)
00000052.00054473 05c5948a Wed Oct 29 2014 14:58:47 +01:00 [kern_ndmpd:info:1951] [16184] INFO: DATA: query 3872053248 bytes in DATA_OP_BACKUP (0)
00000052.00054474 05c5962e Wed Oct 29 2014 14:59:29 +01:00 [kern_ndmpd:info:1951] [16184] INFO: MOVER: query 3874881536 bytes, 59126 records 40.63KB/s (avg 58.76KB/s) (0) rst5a
00000052.00054484 05c5a0e4 Wed Oct 29 2014 15:04:03 +01:00 [kern_ndmpd:info:1951] [16184] INFO: DATA: query 3882130432 bytes in DATA_OP_BACKUP (0)
00000052.00054485 05c5a0e4 Wed Oct 29 2014 15:04:03 +01:00 [kern_ndmpd:info:1951] [16184] INFO: MOVER: received ABORT command
00000052.00054486 05c5a0e4 Wed Oct 29 2014 15:04:03 +01:00 [kern_ndmpd:info:1951] [16184] INFO: MOVER: requesting ABORT
00000052.00054487 05c5a166 Wed Oct 29 2014 15:04:16 +01:00 [kern_ndmpd:info:1951] [16184] INFO: DATA notification state 0 (SESS_STATE: IDLE) event 10 (EVENT: STATE CHANGE)
00000052.00054488 05c5a166 Wed Oct 29 2014 15:04:16 +01:00 [kern_ndmpd:info:1951] [16184] INFO: MOVER: Tape writing operation terminated
00000052.00054489 05c5a166 Wed Oct 29 2014 15:04:16 +01:00 [kern_ndmpd:info:1951] [16184] INFO: MOVER halt on 'aborted': MOVER operation terminated
00000052.0005448a 05c5a166 Wed Oct 29 2014 15:04:16 +01:00 [kern_ndmpd:info:1951] [16184] ERROR: DATA: Backup terminated (for /vol/vol1/.snapshot/2014_q3/snapvault).
00000052.0005448b 05c5a166 Wed Oct 29 2014 15:04:16 +01:00 [kern_ndmpd:info:1951] [16184] INFO: DATA: received ABORT command
00000052.0005448c 05c5a166 Wed Oct 29 2014 15:04:16 +01:00 [kern_ndmpd:info:1951] [16184] ERROR: DATA: Rejecting ABORT request for DATA_OP_HALT_ABORT state.
00000052.0005448d 05c5a166 Wed Oct 29 2014 15:04:16 +01:00 [kern_ndmpd:info:1951] [16184] INFO: DATA: received STOP command
00000052.0005448e 05c5a166 Wed Oct 29 2014 15:04:16 +01:00 [kern_ndmpd:info:1951] [16184] INFO: SCSI: TAPE MTIO REWIND 1 rst5a
00000052.00054493 05c5a4e9 Wed Oct 29 2014 15:05:46 +01:00 [kern_ndmpd:info:1951] [16184] INFO: SCSI: TAPE MTIO BSF 1 rst5a (-0:00:01)
00000052.00054494 05c5a4e9 Wed Oct 29 2014 15:05:46 +01:00 [kern_ndmpd:info:1951] [16184] INFO: SCSI: TAPE MTIO UNLOAD 1 rst5a
00000052.00054495 05c5a4e9 Wed Oct 29 2014 15:05:46 +01:00 [kern_ndmpd:info:1951] [16184] NOTICE: SCSI: UNLOAD: rst5a REWINDING
00000052.00054496 05c5a4e9 Wed Oct 29 2014 15:05:46 +01:00 [kern_ndmpd:info:1951] [16184] NOTICE: SCSI: UNLOAD: rst5a UNLOADING...
00000052.00054497 05c5a626 Wed Oct 29 2014 15:06:18 +01:00 [kern_ndmpd:info:1951] [15290] INFO: TEST READY: STD 0x70 (Current) sense 2 (NOT READY) (len 64) {rst1a} (-0:00:01)
00000052.00054498 05c5a626 Wed Oct 29 2014 15:06:18 +01:00 [kern_ndmpd:info:1951] [15290] INFO: TEST READY: ASC/Q 0401 [LUN Not Ready, Calibration in Process] (-0:00:01)
Any idees why this happend?
Thanks!
/C
I use : TSM 6.3.4, Win2012, Netapp Ontap 8.1.4P2 7-mode, FC attached tape drives configured with datamovers and virtualvolumes.
I have some problems with my NDMP backups. I run NDMP backups frequently on differnt size of virtualvolumes. But I have a some volumes that I always have problem to dump. I can't find what the problem is. Below you can see two of the ndmpd errors from the netapp ndmpd log. The first gets BAD_MEDIA, and the other one gets a "requesting ABORT"
First dump that Went wrong today:
00000052.0005428f 05c38cce Wed Oct 29 2014 11:17:01 +01:00 [kern_ndmpd:info:1951] [16184] INFO: MOVER: query 3434610688 bytes, 52408 records 36.63KB/s (avg 65.69KB/s) (0) rst5a
00000052.00054294 05c39755 Wed Oct 29 2014 11:21:30 +01:00 [kern_ndmpd:info:1951] [16184] INFO: DATA: query 3443948544 bytes in DATA_OP_BACKUP (0)
00000052.00054295 05c397e9 Wed Oct 29 2014 11:21:45 +01:00 [kern_ndmpd:info:1951] [15229] INFO: DATA: query 2142091343872 bytes in DATA_OP_BACKUP (0)
00000052.00054296 05c397e9 Wed Oct 29 2014 11:21:45 +01:00 [kern_ndmpd:info:1951] [15229] INFO: MOVER: query 2142091280384 bytes, 32685719 records 51.61KB/s (avg 21.33MB/s) (0) rst4a
00000052.00054297 05c39850 Wed Oct 29 2014 11:21:55 +01:00 [kern_ndmpd:info:1951] [15229] INFO: DATA notification state 5 (SESS_STATE: HALTING) event 6 (EVENT: BAD_MEDIA)
00000052.00054298 05c39850 Wed Oct 29 2014 11:21:55 +01:00 [kern_ndmpd:info:1951] [15229] ERROR: DATA: Backup terminated: EVENT: BAD_MEDIA (for /vol/vol2/.snapshot/2014_q3/groups/A/JKP)
00000052.00054299 05c39850 Wed Oct 29 2014 11:21:55 +01:00 [kern_ndmpd:info:1951] [15229] INFO: MOVER: signal HALT CLOSE (abort)
00000052.0005429a 05c39850 Wed Oct 29 2014 11:21:55 +01:00 [kern_ndmpd:info:1951] [15229] INFO: MOVER halt on 'closed': MOVER operation successful (CLOSE)
00000052.0005429b 05c39850 Wed Oct 29 2014 11:21:55 +01:00 [kern_ndmpd:info:1951] [15229] INFO: DATA: query 2142091343872 bytes in DATA_OP_HALT_UNKNOWN (0)
00000052.0005429c 05c39850 Wed Oct 29 2014 11:21:55 +01:00 [kern_ndmpd:info:1951] [15229] INFO: MOVER: query 2142091280384 bytes, 32685719 records (avg 21.33MB/s) (0) rst4a
00000052.0005429f 05c39884 Wed Oct 29 2014 11:22:00 +01:00 [kern_ndmpd:info:1951] [15229] INFO: MOVER: received ABORT command
00000052.000542a0 05c39884 Wed Oct 29 2014 11:22:00 +01:00 [kern_ndmpd:info:1951] [15229] ERROR: MOVER: Rejecting ABORT request for MOVER_OP_HALT_CLOSE state.
00000052.000542a1 05c39884 Wed Oct 29 2014 11:22:01 +01:00 [kern_ndmpd:info:1951] [15229] INFO: DATA: received ABORT command (-0:00:01)
00000052.000542a2 05c39884 Wed Oct 29 2014 11:22:01 +01:00 [kern_ndmpd:info:1951] [15229] ERROR: DATA: Rejecting ABORT request for DATA_OP_HALT_UNKNOWN state. (-0:00:01)
00000052.000542a3 05c39884 Wed Oct 29 2014 11:22:01 +01:00 [kern_ndmpd:info:1951] [15229] INFO: DATA: received STOP command (-0:00:01)
00000052.000542a4 05c39884 Wed Oct 29 2014 11:22:01 +01:00 [kern_ndmpd:info:1951] [15229] INFO: SCSI: TAPE MTIO REWIND 1 rst4a (-0:00:01)
00000052.000542a5 05c398f3 Wed Oct 29 2014 11:22:12 +01:00 [kern_ndmpd:info:1951] [16184] INFO: MOVER: query 3445620736 bytes, 52576 records 34.57KB/s (avg 65.51KB/s) (0) rst5a (-0:00:01)
00000052.000542a7 05c39987 Wed Oct 29 2014 11:22:26 +01:00 [kern_ndmpd:info:1951] [15229] INFO: SCSI: TAPE MTIO BSF 1 rst4a
00000052.000542a8 05c39987 Wed Oct 29 2014 11:22:26 +01:00 [kern_ndmpd:info:1951] [15229] INFO: SCSI: TAPE MTIO UNLOAD 1 rst4a
00000052.000542a9 05c39988 Wed Oct 29 2014 11:22:27 +01:00 [kern_ndmpd:info:1951] [15229] NOTICE: SCSI: UNLOAD: rst4a REWINDING
00000052.000542aa 05c39988 Wed Oct 29 2014 11:22:27 +01:00 [kern_ndmpd:info:1951] [15229] NOTICE: SCSI: UNLOAD: rst4a UNLOADING...
00000052.000542ab 05c39aad Wed Oct 29 2014 11:22:56 +01:00 [kern_ndmpd:info:1951] [15290] INFO: TEST READY: STD 0x70 (Current) sense 2 (NOT READY) (len 64) {rst0a} (-0:00:01)
00000052.000542ac 05c39aad Wed Oct 29 2014 11:22:56 +01:00 [kern_ndmpd:info:1951] [15290] INFO: TEST READY: ASC/Q 0401 [LUN Not Ready, Calibration in Process] (-0:00:01)
The second error on another NDMP dump that got wrong later today:
00000052.0005446c 05c58844 Wed Oct 29 2014 14:53:33 +01:00 [kern_ndmpd:info:1951] [16184] INFO: DATA: query 3860307968 bytes in DATA_OP_BACKUP (0) (-0:00:01)
00000052.0005446d 05c589de Wed Oct 29 2014 14:54:14 +01:00 [kern_ndmpd:info:1951] [16184] INFO: MOVER: query 3861774336 bytes, 58926 records 25.07KB/s (avg 58.84KB/s) (0) rst5a (-0:00:01)
00000052.00054473 05c5948a Wed Oct 29 2014 14:58:47 +01:00 [kern_ndmpd:info:1951] [16184] INFO: DATA: query 3872053248 bytes in DATA_OP_BACKUP (0)
00000052.00054474 05c5962e Wed Oct 29 2014 14:59:29 +01:00 [kern_ndmpd:info:1951] [16184] INFO: MOVER: query 3874881536 bytes, 59126 records 40.63KB/s (avg 58.76KB/s) (0) rst5a
00000052.00054484 05c5a0e4 Wed Oct 29 2014 15:04:03 +01:00 [kern_ndmpd:info:1951] [16184] INFO: DATA: query 3882130432 bytes in DATA_OP_BACKUP (0)
00000052.00054485 05c5a0e4 Wed Oct 29 2014 15:04:03 +01:00 [kern_ndmpd:info:1951] [16184] INFO: MOVER: received ABORT command
00000052.00054486 05c5a0e4 Wed Oct 29 2014 15:04:03 +01:00 [kern_ndmpd:info:1951] [16184] INFO: MOVER: requesting ABORT
00000052.00054487 05c5a166 Wed Oct 29 2014 15:04:16 +01:00 [kern_ndmpd:info:1951] [16184] INFO: DATA notification state 0 (SESS_STATE: IDLE) event 10 (EVENT: STATE CHANGE)
00000052.00054488 05c5a166 Wed Oct 29 2014 15:04:16 +01:00 [kern_ndmpd:info:1951] [16184] INFO: MOVER: Tape writing operation terminated
00000052.00054489 05c5a166 Wed Oct 29 2014 15:04:16 +01:00 [kern_ndmpd:info:1951] [16184] INFO: MOVER halt on 'aborted': MOVER operation terminated
00000052.0005448a 05c5a166 Wed Oct 29 2014 15:04:16 +01:00 [kern_ndmpd:info:1951] [16184] ERROR: DATA: Backup terminated (for /vol/vol1/.snapshot/2014_q3/snapvault).
00000052.0005448b 05c5a166 Wed Oct 29 2014 15:04:16 +01:00 [kern_ndmpd:info:1951] [16184] INFO: DATA: received ABORT command
00000052.0005448c 05c5a166 Wed Oct 29 2014 15:04:16 +01:00 [kern_ndmpd:info:1951] [16184] ERROR: DATA: Rejecting ABORT request for DATA_OP_HALT_ABORT state.
00000052.0005448d 05c5a166 Wed Oct 29 2014 15:04:16 +01:00 [kern_ndmpd:info:1951] [16184] INFO: DATA: received STOP command
00000052.0005448e 05c5a166 Wed Oct 29 2014 15:04:16 +01:00 [kern_ndmpd:info:1951] [16184] INFO: SCSI: TAPE MTIO REWIND 1 rst5a
00000052.00054493 05c5a4e9 Wed Oct 29 2014 15:05:46 +01:00 [kern_ndmpd:info:1951] [16184] INFO: SCSI: TAPE MTIO BSF 1 rst5a (-0:00:01)
00000052.00054494 05c5a4e9 Wed Oct 29 2014 15:05:46 +01:00 [kern_ndmpd:info:1951] [16184] INFO: SCSI: TAPE MTIO UNLOAD 1 rst5a
00000052.00054495 05c5a4e9 Wed Oct 29 2014 15:05:46 +01:00 [kern_ndmpd:info:1951] [16184] NOTICE: SCSI: UNLOAD: rst5a REWINDING
00000052.00054496 05c5a4e9 Wed Oct 29 2014 15:05:46 +01:00 [kern_ndmpd:info:1951] [16184] NOTICE: SCSI: UNLOAD: rst5a UNLOADING...
00000052.00054497 05c5a626 Wed Oct 29 2014 15:06:18 +01:00 [kern_ndmpd:info:1951] [15290] INFO: TEST READY: STD 0x70 (Current) sense 2 (NOT READY) (len 64) {rst1a} (-0:00:01)
00000052.00054498 05c5a626 Wed Oct 29 2014 15:06:18 +01:00 [kern_ndmpd:info:1951] [15290] INFO: TEST READY: ASC/Q 0401 [LUN Not Ready, Calibration in Process] (-0:00:01)
Any idees why this happend?
Thanks!
/C
