File in mounted snapshot directory cannot be opened in RMAN
Applies to
- NFSv3
- ONTAP 9
- Oracle Recovery Manager (RMAN)
Issue
- File cannot be opened in RMAN which leads to DB issue.
Example:
RMAN-00571: =========================================================== RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS =============== RMAN-00571: =========================================================== RMAN-03009: failure of catalog command on default channel at 01/05/2022 08:35:16 ORA-19625: error identifying file /x/backup.var/y/data/.snapshot/test.2022-01-05_0749/backup/last.controlfile.backup.1 ORA-17503: ksfdopn:11 Failed to open file /x/backup.var/y/data/.snapshot/test.2022-01-05_0749/backup/last.controlfile.backup.1 ORA-17500: ODM err:Communication error on send
- Tracing the communication reveals the NFSv3 error
NFS3ERR_STALE
at the timestamp.
Example:
963 2022-01-05 08:35:16.474151 10.10.10.2 → 10.10.10.250 NFS 222 V3 LOOKUP Call, DH: 0xc997dd15/backup 964 2022-01-05 08:35:16.474250 10.10.10.250 → 10.10.10.2 NFS 102 V3 LOOKUP Reply (Call In 963) Error: NFS3ERR_STALE
- The NFSv3 exported volume is a SnapMirror destination of a relationship type
vault
and when checking the snapshot IDs with the following command, there is a numerical gap in thelogical-snap-id
field between the current (mounted) and previous snapshot and after the SnapMirror update, the id has increased:
::> set adv ::*> snapshot show -volume nfsvol_vault -fields logical-snap-id,create-time
Example:
Last login time: 1/5/2022 08:33:46 vserver volume snapshot create-time logical-snap-id ---------------- --------------------------- ------------------------ ------------------------ --------------- [...] SVMname nfsvol_vault test.2022-01-04_2058 Tue Jan 04 20:58:50 2022 736 SVMname nfsvol_vault othertest.2022-01-05_0000 Wed Jan 05 00:00:01 2022 739 SVMname nfsvol_vault test.2022-01-05_0749 Wed Jan 05 07:50:00 2022 741 5 entries were displayed.
Last login time: 1/5/2022 08:33:56 vserver volume snapshot create-time logical-snap-id ---------------- --------------------------- ------------------------ ------------------------ --------------- SVMname nfsvol_vault test.2022-01-04_2058 Tue Jan 04 20:58:50 2022 736 SVMname nfsvol_vault othertest.2022-01-05_0000 Wed Jan 05 00:00:01 2022 739 SVMname nfsvol_vault test.2022-01-05_0749 Wed Jan 05 07:50:00 2022 742 5 entries were displayed.
- To confirm, the
snapmirror-audit-log
on the destination states no new snapshot copies to transfer and the related snapshot being deleted.
Example:
Wed Jan 5 08:33:45 CET 2022 ManualUpdate[Jan 5 08:33:45]:uuid Operation-Uuid=uuid Group=none Operation-Cookie=0 action=Start source=SVMsource:nfsvol_source destination=SVMname:nfsvol_vault
Wed Jan 5 08:33:45 CET 2022 ManualUpdate[Jan 5 08:33:45]:uuid Operation-Uuid=uuid Group=none Operation-Cookie=0 action=Info No new Snapshot copy to transfer from source SVMsource:nfsvol_source.
Wed Jan 5 08:33:45 CET 2022 ManualUpdate[Jan 5 08:33:45]:uuid Operation-Uuid=uuid Group=none Operation-Cookie=0 action=End source=SVMsource:nfsvol_source destination=SVMname:nfsvol_vault status=Success bytes_transferred=0 network_compression_ratio=1.0:1
Wed Jan 5 08:33:56 CET 2022 StorageEfficientSnapshotRotation[Jan 5 08:33:56]:uuid Operation-Uuid=uuid Group=none Operation-Cookie=0 action=Start source=SVMsource:nfsvol_source destination=SVMname:nfsvol_vault
Wed Jan 5 08:33:56 CET 2022 StorageEfficientSnapshotRotation[Jan 5 08:33:56]:uuid Operation-Uuid=uuid Group=none Operation-Cookie=0 action=Info sm_rpm_snaplist_delete([1581261]): Snapshot snapmirrorPreSE.test.2022-01-05_0749 deleted.
Wed Jan 5 08:33:56 CET 2022 StorageEfficientSnapshotRotation[Jan 5 08:33:56]:uuid Operation-Uuid=uuid Group=none Operation-Cookie=0 action=End source=SVMsource:nfsvol_source destination=SVMname:nfsvol_vault status=Success