2/16 17:05:34 DEBUG: [1][ndmp_door_init:106]:ndmp_door_init: Door server successfully started
 2/16 17:05:34 DEBUG: [1][tlm_ioctl:1168]:tlm_ioctl fd 10 cmd 1225
 2/16 17:05:34 DEBUG: [1][tlm_ioctl:1168]:tlm_ioctl fd 10 cmd 1225
 2/16 17:05:34 DEBUG: [1][tlm_ioctl:1168]:tlm_ioctl fd 10 cmd 1225
 2/16 17:05:34 DEBUG: [1][tlm_enable_barcode:884]:Barcode capability on library 1 enabled.
 2/16 17:05:34 DEBUG: [1][add_lib:289]:lib 1 sid 0 lun 0
 2/16 17:05:34 DEBUG: [1][tlm_ioctl:1168]:tlm_ioctl fd 10 cmd 1225
 2/16 17:05:34 DEBUG: [1][tlm_ioctl:1168]:tlm_ioctl fd 10 cmd 1225
 2/16 17:05:34 DEBUG: [1][tlm_ioctl:1168]:tlm_ioctl fd 10 cmd 1225
 2/16 17:05:34 DEBUG: [1][tlm_init:556]:nlibs 1
 2/16 17:05:34 DEBUG: [1][tlm_ioctl:1168]:tlm_ioctl fd 10 cmd 1225
 2/16 17:05:34 DEBUG: [1][add_drv:439]:vlib(2, 1) sid 1 lun 0
 2/16 17:05:34 DEBUG: [1][tlm_ioctl:1168]:tlm_ioctl fd 10 cmd 1225
 2/16 17:05:34 DEBUG: [1][tlm_ioctl:1168]:tlm_ioctl fd 10 cmd 1225
 2/16 17:05:34 DEBUG: [1][tlm_ioctl:1168]:tlm_ioctl fd 10 cmd 1225
 2/16 17:05:34 DEBUG: [1][tlm_ioctl:1168]:tlm_ioctl fd 10 cmd 1225
 2/16 17:05:34 DEBUG: [1][add_drv:439]:vlib(2, 2) sid 0 lun 0
 2/16 17:05:34 DEBUG: [1][tlm_ioctl:1168]:tlm_ioctl fd 10 cmd 1225
 2/16 17:05:34 DEBUG: [1][tlm_ioctl:1168]:tlm_ioctl fd 10 cmd 1225
 2/16 17:05:34 DEBUG: [1][tlm_ioctl:1168]:tlm_ioctl fd 10 cmd 1225
 2/16 17:05:34 DEBUG: [1][tlm_ioctl:1168]:tlm_ioctl fd 10 cmd 1225
 2/16 17:05:34 DEBUG: [1][tlm_init:564]:vlibs 2
 2/16 17:05:34 DEBUG: [1][inaccbl_drv_warn:507]:Warning: The following drives are not accessible:
 2/16 17:05:34 DEBUG: [1][inaccbl_drv_warn:513]:/dev/rmt/1n
 2/16 17:05:34 DEBUG: [1][inaccbl_drv_warn:513]:/dev/scsi/changer/c2t0d0
 2/16 17:06:03 DEBUG: [4][ndmp_run:306]:connection fd: 11
 2/16 17:06:03 DEBUG: [5][ndmp_send_request:458]:handler->mh_xdr_reply == 0
 2/16 17:06:03 DEBUG: [5][connection_handler:866]:connection_fd: 11
 2/16 17:06:03 DEBUG: [5][hardlink_q_init:66]:qhead = 8167cc8
 2/16 17:06:03 DEBUG: [5][ndmp_process_messages:1172]:reply_expected: FALSE
 2/16 17:06:03 DEBUG: [5][ndmp_process_messages:1252]:received request: 0x900
 2/16 17:06:03 DEBUG: [5][ndmpd_connect_open_v2:170]:set ver to: 4
 2/16 17:06:03 DEBUG: [5][ndmp_process_messages:1280]:no more messages in stream buffer
 2/16 17:06:03 DEBUG: [5][ndmp_process_messages:1172]:reply_expected: FALSE
 2/16 17:06:03 DEBUG: [5][ndmp_process_messages:1252]:received request: 0x103
 2/16 17:06:03 DEBUG: [5][ndmp_process_messages:1280]:no more messages in stream buffer
 2/16 17:06:03 DEBUG: [5][ndmp_process_messages:1172]:reply_expected: FALSE
 2/16 17:06:03 DEBUG: [5][ndmp_process_messages:1252]:received request: 0x901
 2/16 17:06:03 DEBUG: [5][ndmpd_connect_client_auth_v3:449]:auth_type MD5
 2/16 17:06:03 DEBUG: [5][ndmpd_connect_auth_md5:1248]:Authorization granted.
 2/16 17:06:03 DEBUG: [5][ndmp_process_messages:1280]:no more messages in stream buffer
 2/16 17:06:03 DEBUG: [5][ndmp_process_messages:1172]:reply_expected: FALSE
 2/16 17:06:03 DEBUG: [5][ndmp_process_messages:1252]:received request: 0x40a
 2/16 17:06:03 DEBUG: [5][ndmp_connect_sock_v3:1932]:addr 154.2.168.192:43410
 2/16 17:06:03 DEBUG: [5][ndmp_connect_sock_v3:1951]:sock 13
 2/16 17:06:03 DEBUG: [5][ndmp_process_messages:1280]:no more messages in stream buffer
 2/16 17:06:03 DEBUG: [5][ndmp_process_messages:1172]:reply_expected: FALSE
 2/16 17:06:03 DEBUG: [5][ndmp_process_messages:1252]:received request: 0x402
 2/16 17:06:03 DEBUG: [5][ndmp_buffer_get_size:1005]:Local operation: 64512
 2/16 17:06:03 DEBUG: [5][ndmp_buffer_get_size:1010]:xfer_size: 64512
 2/16 17:06:03 DEBUG: [5][ndmpd_save_env:526]:env(FILESYSTEM): "/fridge/testsnap@monthly03"
 2/16 17:06:03 DEBUG: [5][ndmpd_save_env:526]:env(HIST): "n"
 2/16 17:06:03 DEBUG: [5][ndmpd_save_env:526]:env(LEVEL): "0"
 2/16 17:06:03 DEBUG: [5][ndmpd_save_env:526]:env(TYPE): "zfs"
 2/16 17:06:03 DEBUG: [5][ndmpd_save_env:526]:env(UPDATE): "y"
 2/16 17:06:03 DEBUG: [5][ndmpd_save_env:526]:env(USER): "root"
 2/16 17:06:03 DEBUG: [5][ndmpd_save_env:526]:env(ZFS_BACKUP_SIZE): "2152710680"
 2/16 17:06:03 DEBUG: [5][ndmpd_save_env:526]:env(PREFIX): "/fridge/testsnap@monthly03"
 2/16 17:06:03 DEBUG: [5][ndmpd_save_nlist_v3:749]:orig ""
 2/16 17:06:03 DEBUG: [5][ndmpd_save_nlist_v3:750]:dest "/fridge/restore162"
 2/16 17:06:03 DEBUG: [5][ndmpd_save_nlist_v3:751]:name "NULL"
 2/16 17:06:03 DEBUG: [5][ndmpd_save_nlist_v3:752]:node -1
 2/16 17:06:03 DEBUG: [5][ndmpd_save_nlist_v3:753]:fh_info -1
 2/16 17:06:03 DEBUG: [5][ndmpd_zfs_getenv_zfs_backup_size:1639]:ZFS_BACKUP_SIZE: 2152710680
 2/16 17:06:03 DEBUG: [5][ndmpd_zfs_getenv_level:1570]:env(LEVEL): "0"
 2/16 17:06:03 DEBUG: [5][ndmpd_zfs_getenv_zfs_mode:1456]:env(ZFS_MODE) not specified, defaulting to recursive
 2/16 17:06:03 DEBUG: [5][ndmpd_zfs_getenv_zfs_force:1524]:env(ZFS_FORCE) not specified, defaulting to FALSE
 2/16 17:06:03 DEBUG: [5][ndmpd_zfs_getenv_update:1596]:env(UPDATE): "y"
 2/16 17:06:03 DEBUG: [5][ndmpd_zfs_getenv_dmp_name:1610]:env(DMP_NAME) not specified, defaulting to 'level'
 2/16 17:06:03 DEBUG: [5][ndmpd_zfs_restore_pathvalid:1331]:restore path: fridge/restore162
 2/16 17:06:03 DEBUG: [5][ndmp_send_request:458]:handler->mh_xdr_reply == 0
 2/16 17:06:03 NOTICE: [5][ndmpd_zfs_dma_log:2436]:'zfs' recover starting
 2/16 17:06:03 DEBUG: [5][ndmp_process_messages:1280]:no more messages in stream buffer
 2/16 17:06:03 DEBUG: [7][ndmpd_remote_read_v3:1781]:ns_data.dd_xx: [0, 0, 0, 0, 0]
 2/16 17:06:03 DEBUG: [7][ndmpd_remote_read_v3:1836]:to NOTIFY_DATA_READ [0, 18446744073709551615]
 2/16 17:06:03 DEBUG: [7][ndmp_send_request:458]:handler->mh_xdr_reply == 0
 2/16 17:06:03 DEBUG: [5][ndmp_process_messages:1172]:reply_expected: FALSE
 2/16 17:06:03 DEBUG: [5][ndmp_process_messages:1252]:received request: 0x400
 2/16 17:06:03 DEBUG: [5][ndmp_process_messages:1280]:no more messages in stream buffer
 2/16 17:06:03 DEBUG: [7][ndmpd_zfs_header_read:443]:tape header: NDMPUTF8MAGIC; 0 0; 64512 
 2/16 17:06:03 DEBUG: [8][ndmpd_zfs_restore_recv_write:913]:nz_zfs_force: 0
 2/16 17:06:03 DEBUG: [9][ndmpd_remote_read_v3:1781]:ns_data.dd_xx: [18446744073709487103, 0, 18446744073709551615, 64512, 0]
 2/16 17:06:03 DEBUG: [9][ndmpd_remote_read_v3:1781]:ns_data.dd_xx: [18446744073709422591, 0, 18446744073709551615, 129024, 0]
 2/16 17:06:03 DEBUG: [9][ndmpd_remote_read_v3:1781]:ns_data.dd_xx: [18446744073709358079, 0, 18446744073709551615, 193536, 0]
 2/16 17:06:03 DEBUG: [9][ndmpd_remote_read_v3:1781]:ns_data.dd_xx: [18446744073709293567, 0, 18446744073709551615, 258048, 0]
 2/16 17:06:03 DEBUG: [9][ndmpd_remote_read_v3:1781]:ns_data.dd_xx: [18446744073709229055, 0, 18446744073709551615, 322560, 0]
 2/16 17:06:03 DEBUG: [9][ndmpd_remote_read_v3:1781]:ns_data.dd_xx: [18446744073709164543, 0, 18446744073709551615, 387072, 0]