Avamar: Data Domain Integration: Replication fails with: 5009-filecopy operation failed (nfs: I/O error)
Summary: Avamar - Data Domain Integration: Replication failing with "Err: 5009-filecopy operation failed (nfs: I/O error)"
Symptoms
Replication fails with the following errors:
(A sample from the Avamar logs):
2020-02-26 11:27:39 avtar Info <42385>: id:1 Range-Replication selected because it is supported since DDOS 6.0 (container.1.cdsf)
2020-02-26 11:27:39 avtar Info <40160>: - Establishing a connection to the Data Domain system with basic authentication (Connection mode: A:0 E:0).
2020-02-26 11:27:39 avtar Info <40160>: - Establishing a connection to the Data Domain system with basic authentication (Connection mode: A:0 E:0).
2020-02-26 11:27:39 avtar Info <40160>: - Establishing a connection to the Data Domain system with basic authentication (Connection mode: A:0 E:0).
2020-02-26 11:27:40 avtar Info <40160>: - Establishing a connection to the Data Domain system with basic authentication (Connection mode: A:0 E:0).
2020-02-26 11:27:41 avtar Error <0000>: Replication failed - id: 4, unexpected exception caught: ddr_replthread:4:replicateSlice: ddp_filecopy_status failed
[24648] [140103118698240] Wed Feb 26 11:27:41 2020
ddp_filecopy_status() failed, start_offset[0], length[20971520], Err: 5009-filecopy operation failed (nfs: I/O error)
[24648] [140103120803584] Wed Feb 26 11:27:40 2020
ddp_filecopy_stop() failed, Err: 5004-nfs filecopy stop failed (nfs: No such file or directory)
...
[24648] [140103116592896] Wed Feb 26 11:27:40 2020
ddp_filecopy_stop() failed, Err: 5004-nfs filecopy stop failed (nfs: No such file or directory)
[24648] [140103180687104] Wed Feb 26 11:27:39 2020
ddp_access() failed, Path avamar-123456789/STAGING/5be457387ae27688587b250879ad303532b2fd33/BACKUP-C97A790FDAC757D5B883F6E3A5BF0BE9344B0355-1D5EC41EE3438C2, mode 0 Err: 5004-nfs lookup failed (nfs: No such file or directory)
[24648] [140103180687104] Wed Feb 26 11:27:39 2020
ddp_access() failed, Path avamar-123456789/STAGING/5be457387ae27688587b250879ad303532b2fd33/BACKUP-C97A790FDAC757D5B883F6E3A5BF0BE9344B0355-1D5EC41EE3438C2, mode 0 Err: 5004-nfs lookup failed (nfs: No such file or directory)
2020-02-26 11:27:41 avtar Error <0000>: Replication failed - id: 5, unexpected exception caught: ddr_replthread:5:replicateSlice: ddp_filecopy_status failed
...
[24648] [140103116592896] Wed Feb 26 11:27:41 2020
ddp_filecopy_status() failed, start_offset[0], length[20971520], Err: 5009-filecopy operation failed (nfs: I/O error)
[24648] [140103120803584] Wed Feb 26 11:27:41 2020
ddp_filecopy_status() failed, start_offset[0], length[20971520], Err: 5009-filecopy operation failed (nfs: I/O error)
...
[24648] [140103121856256] Wed Feb 26 11:27:40 2020
ddp_filecopy_stop() failed, Err: 5004-nfs filecopy stop failed (nfs: No such file or directory)
[24648] [140103119750912] Wed Feb 26 11:27:40 2020
ddp_filecopy_stop() failed, Err: 5004-nfs filecopy stop failed (nfs: No such file or directory)
[24648] [140103117645568] Wed Feb 26 11:27:40 2020
ddp_filecopy_stop() failed, Err: 5004-nfs filecopy stop failed (nfs: No such file or directory)
2020-02-26 11:27:42 avtar Error <18788>: Replication failed - a replication thread encountered error 4910, desc: Unknown exception caught.
2020-02-26 11:27:42 avtar Info <18789>: Backup Replication Stats: original backup size: 0 (0 bytes), precompression size: 0 (0 bytes), network bytes sent: 0 (0 bytes), sent: 0.00%
2020-02-26 11:27:42 avtar Error <18797>: Replication failed - The replicator returned an error.
2020-02-26 11:27:42 avtar Error <18773>: MReplication failed -- backup: 1D5EC41EE3438C2, from DD-6800-1.company.com(1):avamar-134567890 to DD-6800-2.company.com(1):avamar-123456789, DDR result code: 4912, desc: Replication failed
2020-02-26 11:27:43 avtar Warning <18125>: Calling DDR_REPLICATE returned result code:5009 message:I/O error
2020-02-26 11:27:43 avtar Error <10612>: Replication failed -- could not replicate file /cur/5be457387ae27688587b250879ad303532b2fd33/1D5EC41EE3438C2/ddr_files.xml to /STAGING/5be457387ae27688587b250879ad303532b2fd33/BACKUP-C97A790FDAC757D5B883F6E3A5BF0BE9344B0355-1D5EC41EE3438C2/ddr_files.xml, LSU: avamar-123456789, DDR result code: 5009, desc: I/O error
2020-02-26 11:27:43 avtar Info <40176>: - Multi-stream restore summary (current 0, max active 0, max cloned 0, total cloned 0, ddr handle 2):
2020-02-26 11:27:43 avtar FATAL <0000>: Replication failed
2020-02-26 11:27:43 avtar FATAL <40009>: DDR encountered errors.
2020-02-26 11:27:43 avtar Info <9772>: Starting graceful (staged) termination, DDR_ERROR event received (fatal severity) (wrap-up stage)
2020-02-26 11:27:43 avtar Info <0000>: Entering the 'final' phase of termination, DDR_ERROR need to exit)
2020-02-26 11:27:43 avtar Info <40176>: - Multi-stream restore summary (current 0, max active 0, max cloned 0, total cloned 0, ddr handle 2):
2020/02/26-18:27:43.18948 [avtar] INTERNAL ERROR: <0001> assert error (result == MSG_ERR_NONE), /local/jenkins/workspace/server_rollup_hotfix_SLES11-64/src/avtar/ade/adelib/interfaceade.cpp line 396
2020-02-26 11:27:43 avtar Info <5675>: Replicated 0 of 2 backups (0 errors) for client "test-files.company.com"
2020-02-26 11:27:43 avtar Error <6655>: Replicate interrupted.
2020-02-26 11:27:43 avtar Info <7925>: Restored 0 bytes from selection(s) with 0 bytes in 1 files
2020-02-26 11:27:43 avtar Info <7883>: Finished at 2020-02-26 11:27:43 MST, Elapsed time: 0000h:00m:04s
2020-02-26 11:27:43 avtar Info <40176>: - Multi-stream restore summary (current 0, max active 0, max cloned 0, total cloned 0, ddr handle 1):
2020-02-26 11:27:43 avtar Info <6149>: Error summary: 14 errors: 6655, 18773, 10612, 18797, 40009, 18788, 0(7)
2020-02-26 11:27:43 avtar Info <8468>: Sending wrapup message to parent
2020-02-26 11:27:43 avtar Info <5314>: Command failed (14 errors, 2 warnings, exit code 10007: miscellaneous error)
Cause
Although error "Err: 5009-filecopy operation failed (nfs: I/O error)" is a generic error for Data Domain issues. More investigation is needed on the Data Domain to find the root cause.
In this instance, the issue was caused because encryption was not configured the same way on the source and target Data Domains.
The following events were reported in the log:
02/26 22:01:51.161 (tid 0x7fa4fa49ffe0): filecopy ctx 541 dst DD-6800-2.company.com: ASSOC failed: Encrypted replication incompatible between source and destination (5342) (5342)
02/26 22:01:51.161 (tid 0x7fa4fa49ffe0): NOTICE: MSG-REPL-00508: filecopy ctx 541: Replication: originator disconnected from dst DD-6800-2.company.com
02/26 22:01:51.161 (tid 0x7fa4fa49ffe0): filecopy failed for , errno=5342, errstr=ASSOC failed: Encrypted replication incompatible between source and destination (5342)
02/26 22:01:51.161 (tid 0x7fa4fa49ffe0): nfc_worker - Unrecoverable filecopy for src_path: /data/col1/avamar-123456789/cur/5be457387ae27688587b250879ad303532b2fd33/1D5ECC7D985F54C/container.1.cdsf error = 5342. (Not attempting retry)
02/26 22:01:51.161 (tid 0x7fa4fa49ffe0): ERROR: MSG-NFS-00005: Failed to do a filecopy, err = [5342: ASSOC failed: Encrypted replication incompatible between source and destination (5342), ddr/repl/lrepl_originator.c, filecopy_do_associate, 1585]
02/26 22:01:51.162 (tid 0x7fa4fa49ffe0): nfc_worker - filecopy_send_file completed for task=64 filecopy idx=64 error=5
This was verified by checking the encryption setting on the source and target (or destination) Data Domains:
Source:
ddboost file-replication option show encryption
Encryption for file-replication is: disabled
Target:
ddboost file-replication option show encryption
Encryption for file-replication is: enabled
Resolution
1. Verify if encryption should be enabled or disabled on both Data Domains.
2. Log in to the destination that has the incorrect encryption configuration.
3. Check, set, and verify the encryption:
To enable encryption:
ddboost file-replication option show encryption
Encryption for file-replication is: disabled
Authentication-mode is: anonymous
ddboost file-replication option set encryption enabled
Encryption for file-replication set to "enabled".
ddboost file-replication option show encryption
Encryption for file-replication is: enabled
Authentication-mode is: anonymous
To disable encryption:
ddboost file-replication option show encryption
Encryption for file-replication is: enabled
Authentication-mode is: anonymous
ddboost file-replication option set encryption disabled
Encryption for file-replication set to "disabled".
ddboost file-replication option show encryption
Encryption for file-replication is: disabled
Authentication-mode is: anonymous
4. Restart ddboost on the Data Domain where encryption was enabled or disabled the encryption.
ddboost status
DD Boost status: enabled
ddboost disable
The 'ddboost disable' command aborts running DD Boost operations.
Are you sure? (yes|no) [no]: y
ok, proceeding.
DD Boost disabled.
ddboost enable
DD Boost enabled.
ddboost status
DD Boost status: enabled
5. Re-run replication.