Subscribe

C-mode NDMP restore error

[ Edited ]

I am using a 3-way NDMP backup with the c-mode filer. I am able to perform backups without problem and restores to the original location. Restore to different location works also as long as the volume is the same as the backup. However when I attempt to do a redirected restore to a different volume, I get NDMP ILLEGAL ARS errors. It doesn't appear to like the filesystem name provided. Is this a limitation on the C-mode Netapp? 

 

This feature was working in the past on 7-mode systems on varying versions. Currently our C-mode system is running 8.2. 

 

ndmp.log debug: 

 

00000015.013dde1b 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] INFO: DATA: START RECOVER request: nlist size 1
00000015.013dde1c 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: ResList (initial restore list) 0x808f27b40 size 1
00000015.013dde1d 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: [0/1] src_path='/'
00000015.013dde1e 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: [0/1] original_path='(null)'
00000015.013dde1f 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: [0/1] node 0 fh_info 0
00000015.013dde20 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: [0/1] dst_fs='(null)'
00000015.013dde21 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: [0/1] vserve='(null)'
00000015.013dde22 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: [0/1] dst_path='/fas2246-vs1/fas2246_dale1/rest/'
00000015.013dde23 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: ResList (final initial restore list) 0x808f27b40 size 1
00000015.013dde24 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: [0/1] src_path='/'
00000015.013dde25 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: [0/1] original_path='(null)'
00000015.013dde26 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: [0/1] node 0 fh_info 0
00000015.013dde27 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: [0/1] dst_fs='fas2246_dale1'
00000015.013dde28 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: [0/1] vserve='fas2246-vs1'
00000015.013dde29 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: [0/1] dst_path='/rest/'
00000015.013dde2a 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: protocol : p->protocol_number=0 protocol_num=4
00000015.013dde2b 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: protocol : p->protocol_number=4 protocol_num=4
00000015.013dde2c 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: local_request: 0x7fffffffd800
00000015.013dde2d 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: generic_xmit_ndmp_message: start
00000015.013dde2e 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: DMA<<S V4 sequence=15 (0xf)
00000015.013dde2f 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: Time_stamp=0x548b3ade (Dec 12 18:58:38 2014)
00000015.013dde30 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: message type=0 (NDMP4_MESSAGE_REQUEST)
00000015.013dde31 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: message_code=0x603 (NDMP4_LOG_MESSAGE)
00000015.013dde32 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: reply_sequence=0 (0x0)
00000015.013dde33 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: error_code=0 (NDMP4_NO_ERR)
00000015.013dde34 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: log_type=2 (NDMP4_LOG_ERROR)
00000015.013dde35 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: message_id=1 (0x1)
00000015.013dde36 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: entry='START RECOVER Filesystem set to an unexpected value\n'
00000015.013dde37 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: XDR_Stream::message_end: sending 100 bytes with buf 0x808eb5000
00000015.013dde38 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: BUF_Stream::writeq: fd=10 ndmp_io_process buf 0x808eb5000 len 100 space 2048 siz 2048 i0 d0
00000015.013dde39 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: generic_xmit_ndmp_message: done
00000015.013dde3a 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: free_ndmp_req_request: not allocated 0x7fffffffd800 (next 0x0)
00000015.013dde3b 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] ERROR: START RECOVER Filesystem set to an unexpected value
00000015.013dde3c 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: cb_ndmp4_data_start_recover: called
00000015.013dde3d 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: generic_xmit_ndmp_message: start
00000015.013dde3e 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: DMA<<S V4 sequence=16 (0x10)
00000015.013dde3f 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: Time_stamp=0x548b3ade (Dec 12 18:58:38 2014)
00000015.013dde40 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: message type=1 (NDMP4_MESSAGE_REPLY)
00000015.013dde41 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: message_code=0x402 (NDMP4_DATA_START_RECOVER)
00000015.013dde42 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: reply_sequence=14 (0xe)
00000015.013dde43 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: error_code=0 (NDMP4_NO_ERR)
00000015.013dde44 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: error=9 (NDMP4_ILLEGAL_ARGS_ERR)
00000015.013dde45 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: XDR_Stream::message_end: sending 32 bytes with buf 0x808eb5000
00000015.013dde46 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: BUF_Stream::writeq: fd=10 ndmp_io_process buf 0x808eb5000 len 32 space 2048 siz 2048 i0 d0
00000015.013dde47 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: generic_xmit_ndmp_message: done
00000015.013dde48 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: free_ndmp_req_request: put on free pool 0x808eb0580 (0)
00000015.013dde49 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: DATA start_recover: eval_recover_env_list failed
00000015.013dde4a 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: generic_dispatch: action done
00000015.013dde4b 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: generic_dispatch: done
00000015.013dde4c 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: xdr_msg_input: done
00000015.013dde4d 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: io loop: output check
00000015.013dde4e 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: io loop: close signal check
00000015.013dde4f 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: Time_Out::Timer 0x808f27ac0 1418411014.967810 vs 1418410718.94121 (next 0x0)
00000015.013dde50 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: MGMT_RPC::Timer
00000015.013dde51 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: io loop: MGMT RPC release pending
00000015.013dde52 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: io loop: loop top
00000015.013dde53 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: Time_Out::next timeout 1418411014.967810
00000015.013dde54 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: MGMT_RPC::poll_time
00000015.013dde55 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: io loop: read and write mask gen
00000015.013dde56 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: io loop: read (listen) gen
00000015.013dde57 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: io loop: SELECT high 43 read 40000100500 write 0 (st 120.0)
00000015.013dde58 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: io loop: ACTIVE cnt=1 rd=0x400 wr=0x0 (wt 120.0)
00000015.013dde59 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: io loop: listen check
00000015.013dde5a 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: io loop: input check
00000015.013dde5b 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: BUF_Stream::input: fd=10 spaceleft 2048 (ndmp_io_process)
00000015.013dde5c 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: BUF_Stream::input: fd=10 read 28 (ndmp_io_process)
00000015.013dde5d 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: BUF_Stream::read_dispatch: fd=10 input cnt=28 (ndmp_io_process)
00000015.013dde5e 0a762087 Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: BUF_Stream::message_read: in 0x808eb8000 with 28 to 0x808eb9800
00000015.013dde5f 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: BUF_Stream::message_read: rec_mark 0x80000018 len 24
00000015.013dde60 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: BUF_Stream::message_read: data_len=24 total_len=28 in_count=28
00000015.013dde61 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: BUF_Stream::message_read: calling 0x808e61900 with buf 0x808eb9800 len 24
00000015.013dde62 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: xdr_msg_input: start msg len=24 0x808e61900
00000015.013dde63 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: xdr_msg_input: normal dispatch to V4
00000015.013dde64 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: ndmp_dispatch: start
00000015.013dde65 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: new_ndmp_req_request: used 0x808eb0580 (1)
00000015.013dde66 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: DMA>>S V4 sequence=15 (0xf)
00000015.013dde67 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: Time_stamp=0x548b3ade (Dec 12 18:58:38 2014)
00000015.013dde68 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: message type=0 (NDMP4_MESSAGE_REQUEST)
00000015.013dde69 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: message_code=0x902 (NDMP4_CONNECT_CLOSE)
00000015.013dde6a 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: reply_sequence=16 (0x10)
00000015.013dde6b 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: error_code=0 (NDMP4_NO_ERR)
00000015.013dde6c 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: generic_ndmp_dispatch bytes left 0 (pre-body decode)
00000015.013dde6d 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: generic_ndmp_dispatch bytes left 0 (post body decode)
00000015.013dde6e 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: generic_dispatch: action start
00000015.013dde6f 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: free_ndmp_req_request: put on free pool 0x808eb0580 (0)
00000015.013dde70 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: protocol : p->protocol_number=0 protocol_num=0
00000015.013dde71 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: service_terminate called
00000015.013dde72 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: received CLOSE command from [10.25.112.43].56679
00000015.013dde73 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: ndmp_server_connect: called
00000015.013dde74 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: local_request: 0x7fffffffe340
00000015.013dde75 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: generic_xmit_ndmp_message: start
00000015.013dde76 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: DMA<<S V0 Sequence=17
00000015.013dde77 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: Time_stamp=0x548b3ade (Dec 12 18:58:38 2014)
00000015.013dde78 0a76208e Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: Message type=0 (NDMP0_REQUEST)
00000015.013dde79 0a76208f Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: Message procedure=0x502 (NDMP0_NOTIFY_CONNECTED)
00000015.013dde7a 0a76208f Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: Reply sequence=0
00000015.013dde7b 0a76208f Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: Error=0 (NDMP0_NO_ERR)
00000015.013dde7c 0a76208f Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: reason=1 (NDMP0_SHUTDOWN)
00000015.013dde7d 0a76208f Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: protocol_version=4
00000015.013dde7e 0a76208f Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: text_reason='Connection shutdown'
00000015.013dde7f 0a76208f Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: XDR_Stream::message_end: sending 60 bytes with buf 0x808eb5000
00000015.013dde80 0a76208f Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: BUF_Stream::writeq: fd=10 ndmp_io_process buf 0x808eb5000 len 60 space 2048 siz 2048 i0 d0
00000015.013dde81 0a76208f Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: generic_xmit_ndmp_message: done
00000015.013dde82 0a76208f Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: free_ndmp_req_request: not allocated 0x7fffffffe340 (next 0x0)
00000015.013dde83 0a76208f Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: BUF_Stream::cleanup_ipc_bp: called
00000015.013dde84 0a76208f Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: BUF_Stream::cleanup_ipc_bp: fd=42 (session mgmt ipc)
00000015.013dde85 0a76208f Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: BUF_Stream::start_close_work: fd=42 found 0x808e7d600 (session mgmt ipc)
00000015.013dde86 0a76208f Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: DATA session_close: called
00000015.013dde87 0a76208f Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] DEBUG: DATA new_request returns 0x808e2da60 (count 2)
00000015.013dde88 0a76208f Fri Dec 12 2014 18:58:38 +00:00 [kern_ndmpd:info:3464] [13963] INFO: DATA&colon; sending backup ABORT

Re: C-mode NDMP restore error

Hi,

did you solve this problem?
I'm seeing the same error on a cDot 8.3 Cluster. Only recovering into original volume works.

 

Tobi

Re: C-mode NDMP restore error

Nope, never was able to resolve the issue. Smiley Sad