Issues backing up Windows Oracle Database guests - VSS failure

[tosis]

Hi there All,

We've updated our VBR implementation to 9.5 update 4 RTM (9.5.4.2399). Now we're waiting for the Day 0 update and likely install immediately. In the interim we've an issue reported as support case 03387499. Hopefully the community can benefit from discussing the highlights of this in the forum.

Prior to the update, while running 9.5.0.1922, we've had the registry key "DisableOracleProcessing" of type DWORD with value of "1" on the Oracle guests and backup has succeeded. Our DBAs have then used other backup methodology in conjunction and it has all worked quite well for our purposes. It seems that VBR is now disregarding this registry flag as of 9.5 update 4. Ultimately I'm asking if this is intended behaviour, and if not, can it be corrected or reimplemented?

Immediately following the update to 9.5.4.2399 our instances with dbases running in NOARCHIVELOG mode now report VSS writer state errors. The VeeamGuestHelper_<date>.log file for 2019-01-29 compared with 2019-01-11 shows that the VSS writer for a Windows-based Oracle Database guest how disregards the registry flag and tries to enumerate the Oracle VSS writer. This is causing backup failure for guests with NOARCHIVELOG databases where this wasn't the case previously.

All the best,
Tosis

Evidence I've collected so far is as follows:
Error from the backup status log

Code: Select all

Failed to prepare guest for hot backup. Error: VSSControl: -2147212300 Backup job failed. Cannot create a shadow copy of the volumes containing writer's data. A VSS critical writer has failed. Writer name: [Oracle VSS Writer - <DatabaseInstance>]. Class ID: [{26d02976-b909-43ad-af7e-62a4f625e372}]. Instance ID: [{02670266-ead4-4d9b-953b-74c9e6d9a4b3}]. Writer's state: [VSS_WS_FAILED_AT_PREPARE_BACKUP]. Error code: [0x800423f4].
Error: VSSControl: -2147212300 Backup job failed. Cannot create a shadow copy of the volumes containing writer's data. A VSS critical writer has failed. Writer name: [Oracle VSS Writer - <DatabaseInstance>]. Class ID: [{26d02976-b909-43ad-af7e-62a4f625e372}]. Instance ID: [{02670266-ead4-4d9b-953b-74c9e6d9a4b3}]. Writer's state: [VSS_WS_FAILED_AT_PREPARE_BACKUP]. Error code: [0x800423f4].

From the guest before update-  VeeamGuestHelper_11012019.log:
11/01/2019 02:00:57   2424                      Contacting VSS engine.
11/01/2019 02:00:57   2424  INFO                    Setting VSS context for backup (VSS_CTX_BACKUP).
11/01/2019 02:00:57   2424                      Contacting VSS engine.. Ok.
11/01/2019 02:00:57   2424                      Collecting writers metadata.
11/01/2019 02:00:57   2424  INFO                        Disabling writers class from VSS
11/01/2019 02:00:57   4996                              Processing 'identity' event.
11/01/2019 02:00:57   4996                              Processing 'identity' event.. Ok.
...
11/01/2019 02:00:58   2424                              Processing collected writer's metadata. Writer instance UID: [{4fea2d57-7fad-4de0-98ab-85b6bacee848}].
11/01/2019 02:00:58   2424  INFO                            The next enumerated writer: [Oracle VSS Writer - <DatabaseInstance>].
11/01/2019 02:00:58   2424  INFO                            Skipping oracle writer. Instance ID: {4fea2d57-7fad-4de0-98ab-85b6bacee848}, writer name: Oracle VSS Writer - <DatabaseInstance>
11/01/2019 02:00:58   2424                              Processing collected writer's metadata. Writer instance UID: [{4fea2d57-7fad-4de0-98ab-85b6bacee848}].. Ok.
...
11/01/2019 02:00:58   2424                              Releasing system resources allocated during the writers metadata gathering stage.
11/01/2019 02:00:58   2424                              Releasing system resources allocated during the writers metadata gathering stage.. Ok.
11/01/2019 02:00:58   2424                      Collecting writers metadata.. Ok.
...
11/01/2019 02:00:59   2424                      Performing discovery phase.. Ok.
11/01/2019 02:00:59   2424                      Creating a shadow copy of the volumes containing writer's data. Backup type: 'VSS_BT_FULL'.
11/01/2019 02:00:59   2424                              Collecting statuses of the writers.
...
11/01/2019 02:00:59   2424                                  [Oracle VSS Writer - ARTPRD] writer's state: [VSS_WS_STABLE]. Writer's class ID: [{26d02976-b909-43ad-af7e-62a4f625e372}]. Writer's instance ID: [{4fea2d57-7fad-4de0-98ab-85b6bacee848}].
11/01/2019 02:00:59   2424  WARN                            Cannot update writer's state data because writer was not enumerated early or disabled. Writer name: [Oracle VSS Writer - <DatabaseInstance>], class ID: [{26d02976-b909-43ad-af7e-62a4f625e372}], instance ID: [{4fea2d57-7fad-4de0-98ab-85b6bacee848}].
...
11/01/2019 02:00:59   2424                              Collecting statuses of the writers.. Ok.



From the the guest after update - VeeamGuestHelper_29012019.log:
29/01/2019 00:25:46   3240                      Contacting VSS engine.
29/01/2019 00:25:46   3240  INFO                    Setting VSS context for backup (VSS_CTX_BACKUP).
29/01/2019 00:25:46   3240                      Contacting VSS engine.. Ok.
29/01/2019 00:25:46   3240                      Collecting writers metadata.
29/01/2019 00:25:46   3240  INFO                        Disabling writers class from VSS
29/01/2019 00:25:46   3620                              Processing 'identity' event.
29/01/2019 00:25:46   3620                              Processing 'identity' event.. Ok.
...
29/01/2019 00:25:47   3240                              Processing collected writer's metadata. Writer instance UID: [{02670266-ead4-4d9b-953b-74c9e6d9a4b3}].
29/01/2019 00:25:47   3240  INFO                            The next enumerated writer: [Oracle VSS Writer - <DatabaseInstance>].
29/01/2019 00:25:47   3240                              Processing collected writer's metadata. Writer instance UID: [{02670266-ead4-4d9b-953b-74c9e6d9a4b3}].. Ok.
...
29/01/2019 00:25:47   3240                              Releasing system resources allocated during the writers metadata gathering stage.
29/01/2019 00:25:47   3240                              Releasing system resources allocated during the writers metadata gathering stage.. Ok.
29/01/2019 00:25:47   3240                      Collecting writers metadata.. Ok.
...
29/01/2019 09:09:08   5840                      Performing discovery phase.. Ok.
29/01/2019 09:09:08   5840                      Creating a shadow copy of the volumes containing writer's data. Backup type: 'VSS_BT_FULL'.
29/01/2019 09:09:08   5840                              Collecting statuses of the writers.
...
29/01/2019 09:09:08   5840                                  [Oracle VSS Writer - <DatabaseInstance>] writer's state: [VSS_WS_FAILED_AT_PREPARE_BACKUP]. Writer's class ID: [{26d02976-b909-43ad-af7e-62a4f625e372}]. Writer's instance ID: [{02670266-ead4-4d9b-953b-74c9e6d9a4b3}].
...
29/01/2019 09:09:08   5840                              Collecting statuses of the writers.. Ok.
29/01/2019 09:09:08   5840  ERR                     The state of a backup critical writer is [VSS_WS_FAILED_AT_PREPARE_BACKUP]. Error code: [0x800423f4]. Writer name: [Oracle VSS Writer - <DatabaseInstance>]. Class ID: [{26d02976-b909-43ad-af7e-62a4f625e372}]. Instance ID: [{02670266-ead4-4d9b-953b-74c9e6d9a4b3}].
29/01/2019 09:09:08   5840                      Creating a shadow copy of the volumes containing writer's data. Backup type: 'VSS_BT_FULL'.. Failed.
29/01/2019 09:09:08   5840              Performing backup steps. Backup type: [VSS_BT_FULL].. Failed.
29/01/2019 09:09:08   5840  INFO        Terminating the snapshot set. Snapshot set ID: [{62994be7-28ba-4b54-bc21-465250ead0c0}].
29/01/2019 09:09:08   5840  INFO        Terminating the snapshot set. Snapshot set ID: [{62994be7-28ba-4b54-bc21-465250ead0c0}].. Ok.
29/01/2019 09:09:08   5840  ERR     Freeze job failed.
29/01/2019 09:09:08   5840  ERR         Backup job failed.
29/01/2019 09:09:08   5840  ERR         Cannot create a shadow copy of the volumes containing writer's data.
29/01/2019 09:09:08   5840  ERR         A VSS critical writer has failed. Writer name: [Oracle VSS Writer - <DatabaseInstance>]. Class ID: [{26d02976-b909-43ad-af7e-62a4f625e372}]. Instance ID: [{02670266-ead4-4d9b-953b-74c9e6d9a4b3}]. Writer's state: [VSS_WS_FAILED_AT_PREPARE_BACKUP]. Error code: [0x800423f4].
29/01/2019 09:09:09   5928  INFO        RPC: Retrieving VSS exception.
29/01/2019 09:09:09   5928                  Job UID: '{fb0a198a-5b0d-4d25-9498-9b3eb260f9d4}'.
29/01/2019 09:09:09   5928                  Error code: '0x800423f4', message: 'Backup job failed.
29/01/2019 09:09:09   5928                  Cannot create a shadow copy of the volumes containing writer's data.
29/01/2019 09:09:09   5928                  A VSS critical writer has failed. Writer name: [Oracle VSS Writer - <DatabaseInstance>]. Class ID: [{26d02976-b909-43ad-af7e-62a4f625e372}]. Instance ID: [{02670266-ead4-4d9b-953b-74c9e6d9a4b3}]. Writer's state: [VSS_WS_FAILED_AT_PREPARE_BACKUP]. Error code: [0x800423f4].'.
29/01/2019 09:09:09   5928  INFO        RPC: Retrieving VSS exception.. Ok.
29/01/2019 09:09:09   2028          Cleaning CRpcServer data.
29/01/2019 09:09:09   2028  INFO        Clearing list of VSS snapshot jobs.
29/01/2019 09:09:09   2028  INFO        Clearing list of VSS snapshot jobs.. Ok.



From the guest before and after - OracleLib.log:
[11.01.2019 02:00:56] <  5424> oralib| Trying to initialize oracle interface
[11.01.2019 02:00:56] <  5424> oralib|   Initializing oracle session
[11.01.2019 02:00:56] <  5424> oralib|   Initializing oracle session ok.
[11.01.2019 02:00:56] <  5424> oralib| Trying to initialize oracle interface ok.
[11.01.2019 02:00:56] <  5948> oralib|   Creating oracle session holder: <DatabaseInstance>. ok.
[11.01.2019 02:00:56] <  5948> oralib|   Getting oracle instance status
[11.01.2019 02:00:56] <  7124> oralib| Getting oracle instance status implementation
[11.01.2019 02:00:56] <  7124> oralib|   Exec oracle query: SELECT STATUS FROM V$INSTANCE
[11.01.2019 02:00:56] <  7124> oralib|   Oracle query result
[11.01.2019 02:00:56] <  7124> oralib|   OPEN 
[11.01.2019 02:00:56] <  7124> oralib|   Oracle instance status: OPEN
[11.01.2019 02:00:56] <  7124> oralib| Getting oracle instance status implementation ok.
[11.01.2019 02:00:56] <  5948> oralib|     Oracle instance status: OPEN
[11.01.2019 02:00:56] <  5948> oralib|   Getting oracle instance status ok.
[11.01.2019 02:00:56] <  5948> oralib|   Getting oracle database status
[11.01.2019 02:00:56] <  3728> oralib| Getting oracle database status implementation
[11.01.2019 02:00:56] <  3728> oralib|   Exec oracle query: SELECT DATABASE_STATUS FROM V$INSTANCE
[11.01.2019 02:00:56] <  3728> oralib|   Oracle query result
[11.01.2019 02:00:56] <  3728> oralib|   ACTIVE 
[11.01.2019 02:00:56] <  3728> oralib|   Oracle database status: ACTIVE
[11.01.2019 02:00:56] <  3728> oralib| Getting oracle database status implementation ok.
[11.01.2019 02:00:56] <  5948> oralib|     Oracle instance status: ACTIVE
[11.01.2019 02:00:56] <  5948> oralib|   Getting oracle database status ok.
[11.01.2019 02:00:56] <  5948> oralib|   Getting oracle database options
[11.01.2019 02:00:56] <  5948> oralib|     Exec oracle query: SELECT OPEN_MODE, LOG_MODE FROM V$DATABASE
[11.01.2019 02:00:56] <  5948> oralib|     Oracle query result
[11.01.2019 02:00:56] <  5948> oralib|     READ WRITE NOARCHIVELOG 
[11.01.2019 02:00:56] <  5948> oralib|   Getting oracle database options ok.
[11.01.2019 02:00:56] <  5948> oralib|   Database (SID: <DatabaseInstance>) skipped from data collection
[11.01.2019 02:00:56] <  5948> oralib|   Destroying oracle session
[11.01.2019 02:00:56] <  5948> oralib|   Destroying oracle session ok.
[11.01.2019 02:00:56] <  5948> oralib|   Collecting environment properties
[11.01.2019 02:00:56] <  5948> oralib|   Collecting environment properties ok.
[11.01.2019 02:00:56] <  5948> oralib|   <OracleOverall serverName="<Server_FQDN>" osName="Windows Server 2012 R2" timeZone="0" />
[11.01.2019 02:00:56] <  5948> oralib| Exploring oracle instances ok.
...
[29.01.2019 00:25:45] <  4780> oralib| Trying to initialize oracle interface with dblink []
[29.01.2019 00:25:45] <  4780> oralib|   Initializing oracle session
[29.01.2019 00:25:46] <  4780> oralib|   Initializing oracle session Failed.
[29.01.2019 00:25:46] <  4780> oralib| Trying to initialize oracle interface with dblink [] Failed.
[29.01.2019 00:25:46] <  4780> oralib| ERR |Oracle session init thread failed
[29.01.2019 00:25:46] <  4780> oralib| >>  |Oracle error has occurred. ORA-01017: invalid username/password; logon denied
[29.01.2019 00:25:46] <  4780> oralib| >>  |
[29.01.2019 00:25:46] <  4780> oralib| >>  |--tr:Failed to create oracle session.
[29.01.2019 00:25:46] <  4780> oralib| >>  |An exception was thrown from thread [4780].
[29.01.2019 00:25:46] <  5100> oralib|   Creating oracle session holder: <DatabaseInstance>. Failed.
[29.01.2019 00:25:46] <  5100> oralib|   Destroying oracle session
[29.01.2019 00:25:46] <  5100> oralib|   Destroying oracle session ok.
[29.01.2019 00:25:46] <  5100> oralib| ERR |Failed to gather database props for SID: <DatabaseInstance>
[29.01.2019 00:25:46] <  5100> oralib| >>  |Oracle error has occurred. ORA-01017: invalid username/password; logon denied
[29.01.2019 00:25:46] <  5100> oralib| >>  |
[29.01.2019 00:25:46] <  5100> oralib| >>  |--tr:Failed to create oracle session.
[29.01.2019 00:25:46] <  5100> oralib| >>  |--tr:Failed to create oracle session holder. SID: <DatabaseInstance>.
[29.01.2019 00:25:46] <  5100> oralib| >>  |An exception was thrown from thread [4780].
[29.01.2019 00:25:46] <  5100> oralib|   Collecting environment properties
[29.01.2019 00:25:46] <  5100> oralib|   Collecting environment properties ok.
[29.01.2019 00:25:46] <  5100> oralib|   <OracleOverall serverName="<Server_FQDN>" osName="Microsoft Windows Server 2012 R2 (64-bit)" timeZone="0" />
[29.01.2019 00:25:46] <  5100> oralib| Exploring oracle instances ok.

[Dima P.]

Hello and welcome to the community tosis.

I've shared your issue with RnD team. I'll get back to your as soon as I hear back anything. Stay tuned.

[Dima P.]

Justin,

I've confirmed that nothing was changed is described logic in Update 4, so this might infrastructure specific issue. Please keep working with out support team and let us know how the investigation goes. Cheers!

[tosis]

Many thanks Dima, the team are presently investigating
I'll feed back when there's more to share with the community.

[Gary_L]

I ran into this exact same issue after upgrading to 9.5.4.2615. Backups worked fine before this. After playing around with different account settings, I added our domain backup account that we use to the ORA_DBA group on the server and restarted the Oracle VSS Writer service. Once that was done the backups are running normally again.

[Gostev]

Thanks a lot Gary for sharing this.

[Nodnarb]

Thanks Gary_L. After upgrading to 9.5 Update 4 we had a minor issue where we got "Unable to perform application-aware processing of Oracle database (SID: <instance name>) : Oracle error has occurred. ORA-01017: invalid username/password; logon denied --tr:Failed to create oracle session. --tr:Failed to create oracle session holder. SID: <instance name>" in the Veeam job e-mail for one of our Oracle on Windows servers (Oracle 11.2). The Veeam job was configured with the correct Oracle user/pass. After adding our domain backup account to the local ORA_DBA group on the server the problem went away.

[kristofjaeken]

Thanks a lot Gary and Nodnarb! I had exactly what nodnard described. And I can confirm all you need to do is add the backup domain account to the local ora_dba group on the windows server and restart the oracle vss writer service. After this change the job runs smoothly again without any errors or warnings. Thanks again!